Handle dnsmasq "extra" logging #174

DL6ER · 2017-12-21T15:13:59Z

By submitting this pull request, I confirm the following (please check boxes, eg [X]) Failure to fill the template will close your PR:

Please submit all pull requests against the development branch. Failure to do so will delay or deny your request

I have read and understood the contributors guide.
I have checked that another pull request for this purpose does not exist.
I have considered, and confirmed that this submission will be valuable to others.
I accept that this submission may not be used, and the pull request closed at the will of the maintainer.
I give this submission freely, and claim no ownership to its content.

How familiar are you with the codebase?:

10

Complete re-write of FTL log file parser to use dnsmasq's UUIDs present in the log if option log-queries=extra is set. This will ensure 100% correctness of the interpreted log files.

One particular difficulty with dnsmasq's extra logging is that it resets the UUID counter to 0 when being restarted. This poisons the whole idea of having UUIDs. A proper failsafe condition (using the idea of UUID generations) has been implemented in the new parser.

Note that this is a breaking change as the "old" log format cannot be read anymore and as such will bump FTL's version to v3.0.

This template was created based on the work of udemy-dl.

Signed-off-by: DL6ER <dl6er@dl6er.de>

…etection into its own subroutine to avoid large repitions of code. Signed-off-by: DL6ER <dl6er@dl6er.de>

Signed-off-by: DL6ER <dl6er@dl6er.de>

…ave a path + removed some debugging output Signed-off-by: DL6ER <dl6er@dl6er.de>

Signed-off-by: DL6ER <dl6er@dl6er.de>

…ries) Signed-off-by: DL6ER <dl6er@dl6er.de>

…IGHUP) Signed-off-by: DL6ER <dl6er@dl6er.de>

Signed-off-by: DL6ER <dl6er@dl6er.de>

…very unique Signed-off-by: DL6ER <dl6er@dl6er.de>

Signed-off-by: DL6ER <dl6er@dl6er.de>

DL6ER · 2017-12-27T12:20:01Z

Still working fine for me with no queries that cannot be determined (see Unknown DNS queries).

[2017-12-27 13:14:45.999]  -> Total DNS queries: 6689
[2017-12-27 13:14:45.999]  -> Cached DNS queries: 2348
[2017-12-27 13:14:45.999]  -> Forwarded DNS queries: 4278
[2017-12-27 13:14:45.999]  -> Exactly blocked DNS queries: 61
[2017-12-27 13:14:45.999]  -> Wildcard blocked DNS queries: 2
[2017-12-27 13:14:45.999]  -> Unknown DNS queries: 0
[2017-12-27 13:14:45.999]  -> Unique domains: 880
[2017-12-27 13:14:45.999]  -> Unique clients: 6
[2017-12-27 13:14:45.999]  -> Known forward destinations: 4

100% accuracy is verified via visual inspection in a few very busy regions.

This PR can be merged at any point to development as the release target v2.13.1 is already branched out. As soon as this PR is merged, I can open additional PRs, e.g. actually utilizing the new data we collect from the reply lines as well as advanced DNSSEC support (which is so far completely ignored by FTL) in smaller, much easier to review pull requests.

…rong but nobody noticed it) Signed-off-by: DL6ER <dl6er@dl6er.de>

AzureMarker · 2017-12-27T15:26:18Z

database.c

- // Already in database
- // logg("Skipping %i",i);
+ if(queries[i].timestamp <= lasttimestamp || queries[i].db || !queries[i].complete)
+ // Already in database or not yet complete
 continue;


If we skip a query while it's still not yet complete and the one after is complete, we would lose the first query. Perhaps change this to a break so that we never add any queries after one which is not complete.

Hmm, not sure if that is a good solution - although it never happend to me so far, this could be a potential dead-lock assuming that dnsmasq didn't write out the result for one query so it would never be completed. What do you think?

Maybe bring back the 200 line check or convert it to a timestamp check. If the query hasn't completed after 2 seconds, assume it's a goner and continue.

Okay, I will in addition compare the time stamp of the query with the current time and break if the query was from within the most recent two seconds. It will have a chance to get saved (or eventually ignored) on the next DB dumping time.

AzureMarker · 2017-12-27T15:27:29Z

request.c

+
+ if(!debug)
+ {
+ sprintf(server_message,"For safety reasons, the command is only available in debugging mode!\n");


Why is this?

Initially this command was supposed to do something different, I will remove this statement here.

AzureMarker · 2017-12-27T15:44:09Z

parser.c

+ if(dnsmasqID < 0)
+ continue;
+
+ // Save forwardID in corresponding query indentified by dnsmasq's ID


Is this comment supposed to reference forwardID or status?

True, will fix this

AzureMarker · 2017-12-27T15:46:21Z

parser.c

- int querytimestamp, overTimetimestamp, timeidx = -1, i;
- extracttimestamp(readbuffer, &querytimestamp, &overTimetimestamp);
-
+ // Save forwardID in corresponding query indentified by dnsmasq's ID


I think this is where that comment came from (see above).

I agree :-)

AzureMarker · 2017-12-27T15:49:38Z

parser.c

+ else if(strstr(readbuffer," config ") != NULL && strstr(readbuffer," is ") != NULL)
+ {
+ // Check query for invalid characters
+ if(!checkQuery(readbuffer, "gravity.list"))


Is this the correct type for wildcards?

Signed-off-by: DL6ER <dl6er@dl6er.de>

… a query more time to get completed Signed-off-by: DL6ER <dl6er@dl6er.de>

pralor-bot · 2018-08-04T18:07:17Z

This pull request has been mentioned on Pi-hole Userspace. There might be relevant details there:

https://discourse.pi-hole.net/t/cache-server-statistics/6092/1

pralor-bot · 2020-05-31T16:04:08Z

This pull request has been mentioned on Pi-hole Userspace. There might be relevant details there:

https://discourse.pi-hole.net/t/tracking-request-status-unambiguously/6091/1

DL6ER added 14 commits December 21, 2017 14:17

Extract dnsmasq's ID from the logged queries

c86e8d9

Signed-off-by: DL6ER <dl6er@dl6er.de>

Modify parser to understand "query" lines with IDs

90494ec

Signed-off-by: DL6ER <dl6er@dl6er.de>

Added proper analysis for "cached" lines + outsourced the timestamp d…

468da59

…etection into its own subroutine to avoid large repitions of code. Signed-off-by: DL6ER <dl6er@dl6er.de>

Initialize query status with 0 (unknown)

a20eb2d

Signed-off-by: DL6ER <dl6er@dl6er.de>

Change the logic FTL uses to treat the counters

9c49155

Signed-off-by: DL6ER <dl6er@dl6er.de>

Properly update time index

678e755

Signed-off-by: DL6ER <dl6er@dl6er.de>

List files like gravity.list, local.list, and hostname.list have to h…

413dd41

…ave a path + removed some debugging output Signed-off-by: DL6ER <dl6er@dl6er.de>

Handle wildcard blocked domains correctly

538e5a3

Signed-off-by: DL6ER <dl6er@dl6er.de>

Handle exactly blocked queries (blocked by black.list)

d276e3b

Signed-off-by: DL6ER <dl6er@dl6er.de>

Have to actually break out of the loops for i to be the queryID

99506f0

Signed-off-by: DL6ER <dl6er@dl6er.de>

Add (undocumented) debugging command over telnet (display unknown que…

541d86b

…ries) Signed-off-by: DL6ER <dl6er@dl6er.de>

Display counter information after re-reading the log file (received S…

24e4f6f

…IGHUP) Signed-off-by: DL6ER <dl6er@dl6er.de>

Extend the new debug command a little bit

478568e

Signed-off-by: DL6ER <dl6er@dl6er.de>

Don't reuse i as counting index where we need it as query ID

f935312

Signed-off-by: DL6ER <dl6er@dl6er.de>

DL6ER added the Enhancement label Dec 21, 2017

DL6ER added this to the v3.0 milestone Dec 21, 2017

DL6ER requested a review from a team December 21, 2017 15:13

DL6ER added 3 commits December 21, 2017 16:15

Update tests with new log format

b61d035

Signed-off-by: DL6ER <dl6er@dl6er.de>

Skip lines without UUID

86393d5

Signed-off-by: DL6ER <dl6er@dl6er.de>

Add the concept of log generations to account for UUIDs that are not …

f416fa5

…very unique Signed-off-by: DL6ER <dl6er@dl6er.de>

DL6ER changed the title ~~[WIP] Handle dnsmasq "extra" logging~~ Handle dnsmasq "extra" logging Dec 21, 2017

DL6ER mentioned this pull request Dec 21, 2017

Enable dnsmasq's extra logging feature pi-hole/pi-hole#1859

Merged

9 tasks

DL6ER added 5 commits December 22, 2017 12:16

Further reduction of code duplication in the parser routine

3d0fc44

Signed-off-by: DL6ER <dl6er@dl6er.de>

Save only complete queries into the database

8035d9f

Signed-off-by: DL6ER <dl6er@dl6er.de>

Merge branch 'development' into new/extra-logging

dc0788c

Add parsing for "reply ... is ..." lines

dac50b1

Signed-off-by: DL6ER <dl6er@dl6er.de>

Save reply type in query struct (can be used somewhere later on)

13b89c7

Signed-off-by: DL6ER <dl6er@dl6er.de>

Output correct counters in log_counter_info() (this has always been w…

7cbf68f

…rong but nobody noticed it) Signed-off-by: DL6ER <dl6er@dl6er.de>

AzureMarker reviewed Dec 27, 2017

View reviewed changes

DL6ER added 3 commits December 28, 2017 20:43

Add global counters for types of replies (and properly GC them)

3346a84

Signed-off-by: DL6ER <dl6er@dl6er.de>

Worked on review comments

dbc9457

Signed-off-by: DL6ER <dl6er@dl6er.de>

Compare age of query against current time to decide if we should give…

d669a65

… a query more time to get completed Signed-off-by: DL6ER <dl6er@dl6er.de>

DL6ER requested a review from AzureMarker December 28, 2017 20:10

AzureMarker approved these changes Dec 28, 2017

View reviewed changes

DL6ER merged commit 21e60e3 into development Dec 28, 2017

DL6ER deleted the new/extra-logging branch December 28, 2017 21:44

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Handle dnsmasq "extra" logging #174

Handle dnsmasq "extra" logging #174

DL6ER commented Dec 21, 2017 •

edited

Loading

DL6ER commented Dec 27, 2017 •

edited

Loading

AzureMarker Dec 27, 2017

DL6ER Dec 28, 2017

AzureMarker Dec 28, 2017

DL6ER Dec 28, 2017

AzureMarker Dec 27, 2017

DL6ER Dec 28, 2017

AzureMarker Dec 27, 2017

DL6ER Dec 28, 2017

AzureMarker Dec 27, 2017

DL6ER Dec 28, 2017

AzureMarker Dec 27, 2017

pralor-bot commented Aug 4, 2018

pralor-bot commented May 31, 2020

Handle dnsmasq "extra" logging #174

Handle dnsmasq "extra" logging #174

Conversation

DL6ER commented Dec 21, 2017 • edited Loading

10

DL6ER commented Dec 27, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pralor-bot commented Aug 4, 2018

pralor-bot commented May 31, 2020

DL6ER commented Dec 21, 2017 •

edited

Loading

DL6ER commented Dec 27, 2017 •

edited

Loading