Query Log shows _all_ queries when filtered for the upstream DNS server with upstreamID=0

[Daxtorim]

Versions

• Pi-hole: v5.2.2
• AdminLTE: v5.2.2
• FTL: v5.3.4

Platform

• OS and version: Raspbian GNU/Linux 10 (buster)

• Platform: RaspberryPi Zero W

Expected behavior

When filtering the Query Log for a certain upstream DNS server (e.g. Cloudflare http://pi.hole/admin/queries.php?forwarddest=one.one.one.one%2353) it should only show queries that were either forwarded, retried, blocked externally, or blocked after CNAME inspection.

Actual behavior / bug

For one of the upstream DNS servers all queries are shown. This includes all blocked and all cached queries. Filtering for some other upstream server shows only forwarded queries; blocked and retried queries are missing.

Steps to reproduce

Steps to reproduce the behavior:

1. Go to the Queries answered by chart.
2. Click on the legend to go to a filtered the Query Log.
3. Sort by status.
4. See error (or check next upstream server for error).

Screenshots

Additional context

I did some investigating and I think the issue is with the upstreamID of each individual query. The faulty behavior appears to only happen when filtering for the upstream server that is associated with upstreamID=0. When filtering for other upstream destinations, only forwarded queries and those blocked after CNAME inspection are shown (although that doesn't always work either, more on that later). There is only this check:

FTL/src/api/api.c

Lines 960 to 976 in 6bd0988

	if(filterforwarddest)
	{
	// Does the user want to see queries answered from blocking lists?
	if(forwarddestid == -2 && query->status != QUERY_GRAVITY
	&& query->status != QUERY_REGEX
	&& query->status != QUERY_BLACKLIST
	&& query->status != QUERY_GRAVITY_CNAME
	&& query->status != QUERY_REGEX_CNAME
	&& query->status != QUERY_BLACKLIST_CNAME)
	continue;
	// Does the user want to see queries answered from local cache?
	else if(forwarddestid == -1 && query->status != QUERY_CACHE)
	continue;
	// Does the user want to see queries answered by an upstream server?
	else if(forwarddestid >= 0 && forwarddestid != query->upstreamID)
	continue;
	}

forwarddestid is arbitrarily set to -2 for blocked queries, to -1 for cached queries and then to the desired upstreamID for certain upstream DNS server. It seems that blocked and cached queries are given an upstreamID of zero by default? So when the queries are sorted to only include queries with upstreamID=0, blocked and cached queries aren't skipped as they should be. I attempted to fix this by simply tightening the condition of the final else if:

else if(( forwarddestid >= 0 && forwarddestid != query->upstreamID) ||
        ((forwarddestid >= 0 && forwarddestid == query->upstreamID) &&
         (query->status == QUERY_GRAVITY ||
          query->status == QUERY_REGEX ||
          query->status == QUERY_BLACKLIST ||
          query->status == QUERY_CACHE)))
    continue;

This does fix the problem, it revealed another issue though.
As hinted on above, queries that are blocked after CNAME inspection aren't always shown for all individual upstream server. In fact, they are only shown for the last upstream server that actually created such a query plus the one with upstreamID=0. Meaning, if several queries where blocked after being forwarded to DNS_1, they would then appear in the Query Log for DNS_1. When subsequent queries are then forwarded to DNS_2 and blocked after CNAME inspection, those queries are correctly displayed in the Query Log for DNS_2. But, now the blocked queries that were sent to DNS_1 are nowhere to be found anymore.
They are still shown when specifically filtering for "blocklist", but when filtering the Query Log for DNS_1 again, the blocked queries are absent, even though they were correctly displayed earlier. Based on a few glimpses I assume this is also the case for retried queries but I can't reliably create retried queries for testing purposes.

Just adding another condition to the check does fix the title issue, I can open a pull request for that if you want. However, the second issue about missing queries remains to be fixed. I don't know if that is also related to a faulty(?) upstreamID. If it is, maybe there is a better solution by fixing how the upstreamID is set in the first place. Unfortunately my understanding of the code falls off a cliff at that point.

[DL6ER]

queries are given an upstreamID of zero by default

Yeah, that's just the initialization value.

---

if(filterforwarddest)

I'm on my way to bed, so I may see this from the wrong angle, but shouldn't we just do something like

// [...]
 	// Does the user want to see queries answered by an upstream server? 
 	else if(forwarddestid >= 0 && forwarddestid != query->upstreamID) 
 		continue; 

	// Skip queries not having been forwarded
	if(forwarddestid >= 0 &&
	   query->status != QUERY_FORWARDED && 
	   query->status != QUERY_RETRIED && 
	   query->status != QUERY_RETRIED_DNSSEC)
		continue;
} 

here? Skipping based on what we want seems easier than doing it based on what we don't want (because we'll forget to change this in the future when new query types may be added).

I also had a quick look on the second issue you're reporting but I don't yet really see what may be happening here. I'll read it again with fresh eyes and will try to reproduce this myself locally. Do you have some simple steps to reproduce this? (probably not, just set two DNS servers and hope the second is chosen at some point).

[Daxtorim]

I guess it wouldn't matter if the new condition is part of the existing else if or if it is a completely separate if. My example skips if it is a query I don't want to see, your example skips if it isn't a query I do want to see.
Personally, I would like to see queries that were blocked after CNAME inspection as well, since they were already forwarded in order to even know it was a CNAME in the first place. Also queries that were blocked externally. Just expand your example with the additional conditions:

        if(forwarddestid >= 0 &&
	   query->status != QUERY_FORWARDED && 
	   query->status != QUERY_RETRIED && 
	   query->status != QUERY_RETRIED_DNSSEC &&
           query->status != QUERY_GRAVITY_CNAME &&
           query->status != QUERY_REGEX_CNAME &&
           query->status != QUERY_BLACKLIST_CNAME &&
           query->status != QUERY_EXTERNAL_BLOCKED_IP &&
           query->status != QUERY_EXTERNAL_BLOCKED_NULL  &&
           query->status != QUERY_EXTERNAL_BLOCKED_NXRA)
		continue;

we'll forget to change this in the future when new query types may be added

You mean status types? That depends on what the new status type says. If it is a blocking status we would need to change my proposal, if it is an allowed status we need to change your proposal. We may forget either way, so not much to be gained on that front, unless you already have a certain type in mind that you want to add later.

To reproduce the second issue I selected a single upstream DNS server, created a simple regex filter (a single consonant like l, a vowel would block almost everything), and used this DNS benchmark tool to quickly produce a few hundred queries (~200 per benchmark, takes maybe 5 seconds). This produced quite a few queries with status Blocked (regex blacklist, CNAME). Then change upstream server and do it again. Repeat a third time and the blocked queries for the second upstream server should have disappeared.

[DL6ER]

You are right. So it doesn't really matter which way we do it. And we will surely forget about it, however, it doesn't seem to be much of a problem as this has now been found also only a long time after this filtering was added. Stepping back for one moment, I don't actually see much of a justification for this filtering at all ;-) Well, maybe if you want to check if some DNS server blocks something another server doesn't block, however, this is not the right tool in this case.

I'm not directly looking at removing this feature right now, however, I do question if it is meaningful at all. What was your motivation to try it (and discover the bug)? Because you just played around and saw the defect or do you actually have a use case for this? You see why I'm asking. When nobody really is using this, we should maybe just remove it instead of fixing it. A proper fix would likely add a new boolean to the query struct was_forwarded and only filter based on this rather than trying to guess from the status if it may have been forwarded. This would also solve the forgetting-to-fix-on-adding-new-query-status issue.

Concerning the second issue you mentioned, I'll try to reproduce it soon. Once I see what is going wrong where, a fix should be close.

We're currently in the transition to the code that should become the new Pi-hole version 6.0

[Daxtorim]

if you want to check if some DNS server blocks something another server doesn't

That, plus to see if one server causes more retried queries than another, and maybe to get a quick glance of response times. In my case random curiosity made me click on all the things, but there are a few scenarios where this filtering is actually useful. The dashboard is a good first step to get an overview of things before you try to further assess any possible issues.

add a new boolean to the query struct was_forwarded

Might as well add was_blocked and simplify the entire check to:

 if(filterforwarddest) 
 { 
 	// Does the user want to see queries answered from blocking lists? 
 	if(forwarddestid == -2 && !was_blocked) 
 		continue; 

 	// Does the user want to see queries answered from local cache? 
 	else if(forwarddestid == -1 && query->status != QUERY_CACHE) 
 		continue; 

 	// Does the user want to see queries answered by an upstream server? 
 	else if((forwarddestid >= 0 && forwarddestid != query->upstreamID) ||
                  (forwarddestid >= 0 && !was_forwarded)) 
 		continue; 
 } 

You still need to determine if something was forwarded and/or blocked to even set those variables but a check closer to the source would probably be preferable.

We're currently in the transition to the code that should become the new Pi-hole version 6.0

Am I correct in assuming that the new/http branch will be part of that? Then the relevant code would be

FTL/src/api/stats.c

Lines 915 to 931 in c0505d7

	if(filterforwarddest)
	{
	// Does the user want to see queries answered from blocking lists?
	if(forwarddestid == -2 && query->status != QUERY_GRAVITY
	&& query->status != QUERY_REGEX
	&& query->status != QUERY_BLACKLIST
	&& query->status != QUERY_GRAVITY_CNAME
	&& query->status != QUERY_REGEX_CNAME
	&& query->status != QUERY_BLACKLIST_CNAME)
	continue;
	// Does the user want to see queries answered from local cache?
	else if(forwarddestid == -1 && query->status != QUERY_CACHE)
	continue;
	// Does the user want to see queries answered by an upstream server?
	else if(forwarddestid >= 0 && forwarddestid != query->upstreamID)
	continue;
	}

which happens to be the exact same code. You actually have a second instance where you check for blocked queries based on the status where you could benefit from a generic was_blocked flag (it's in the same file even):

FTL/src/api/stats.c

Lines 1044 to 1113 in c0505d7

	int api_stats_recentblocked(struct mg_connection *conn)
	{
	unsigned int show = 1;
	// Verify requesting client is allowed to see this ressource
	if(check_client_auth(conn) == API_AUTH_UNAUTHORIZED)
	{
	return send_json_unauthorized(conn);
	}
	// Exit before processing any data if requested via config setting
	get_privacy_level(NULL);
	if(config.privacylevel >= PRIVACY_HIDE_DOMAINS)
	{
	// Minimum structure is
	// {"blocked":null}
	cJSON *json = JSON_NEW_OBJ();
	JSON_OBJ_ADD_NULL(json, "blocked");
	JSON_SEND_OBJECT(json);
	}
	const struct mg_request_info *request = mg_get_request_info(conn);
	if(request->query_string != NULL)
	{
	// Does the user request a non-default number of replies?
	// Note: We do not accept zero query requests here
	get_uint_var(request->query_string, "show", &show);
	}
	// Find most recently blocked query
	unsigned int found = 0;
	cJSON *blocked = JSON_NEW_ARRAY();
	for(int queryID = counters->queries - 1; queryID > 0 ; queryID--)
	{
	const queriesData* query = getQuery(queryID, true);
	if(query == NULL)
	{
	continue;
	}
	if(query->status == QUERY_GRAVITY ||
	query->status == QUERY_REGEX ||
	query->status == QUERY_BLACKLIST ||
	query->status == QUERY_EXTERNAL_BLOCKED_IP ||
	query->status == QUERY_EXTERNAL_BLOCKED_NULL ||
	query->status == QUERY_EXTERNAL_BLOCKED_NXRA ||
	query->status == QUERY_GRAVITY_CNAME ||
	query->status == QUERY_REGEX_CNAME ||
	query->status == QUERY_BLACKLIST_CNAME)
	{
	found++;
	// Ask subroutine for domain. It may return "hidden" depending on
	// the privacy settings at the time the query was made
	const char *domain = getDomainString(query);
	if(domain == NULL)
	{
	continue;
	}
	JSON_ARRAY_REF_STR(blocked, domain);
	}
	if(found >= show)
	break;
	}
	cJSON *json = JSON_NEW_OBJ();
	JSON_OBJ_ADD_ITEM(json, "blocked", blocked);
	JSON_SEND_OBJECT(json);
	}

---

Well, it's your call whether this is worth fixing right now. I don't know what your plans for further v5.x releases are. There is this older issue https://github.com/pi-hole/pi-hole/issues/3418 about the buttons on the dashboard not working that hasn't been fixed yet and was even recently reported again, so there are definitely some people who use this feature every now and again.

[DL6ER]

Might as well add was_blocked [...]

Yeah, that was my idea as well. I'll also have a look for further useful flags. We can have 8 flags for free per used byte.

You still need to determine if something was forwarded and/or blocked to even set those variables but a check closer to the source would probably be preferable.

Yes. There is always on location where this is 100% clear (forward: when sending query upstream, blocked: after checking the lists). Setting the variable to true would be done there. They'd be false by default. It's a bit trickier when restoring from the database, but we cannot have everything (response times, etc. are also not stored).

Am I correct in assuming that the new/http branch will be part of that?

Yes. I copy-pasted most of the code and tweaked it only so far that it compiles and works. I'm working on the bits of the code when I'm also working on the dashboard in parallel.

it's your call whether this is worth fixing right now

Sure, a broken feature doesn't help anyone. If we keep it, we should have it working properly. Pi-hole already samples who is the fastest server and selects this one. And when queries need to be retired, we also retry them with another server to reduce the delay when one of the server is gone.

There is this older issue pi-hole/pi-hole#3418

I moved it into the FTL namespace now.

[DL6ER]

@Daxtorim Could you check if branch fix/querylog_filtering fixes both issues for you? I must admit that I tried exactly what you wrote and wasn't able to see the same defect. However, as it only appeared with you having fixed the first mentioned issue, it may have been a regression from the initial fix.

pihole checkout ftl fix/querylog_filtering

Instead of adding an extra flag for was_forwarded, I changed the default for upstreamID to -1 so anything > -1 always means this query was forwarded. The -1 and -2 (forwarddest) are only used temporarily and never appear in the query struct so there is no conflict here.

I simplified some checks and ensured that the chosen forward destination is also stored in the database with CNAME, etc. queries. This is likely what fixed the other issue you were seeing as FTL wasn't aware of what was the original upstream server a CNAME was sent to after restart (as this data never entered the database).

[yubiuser]

The -1 and -2 (forwarddest) are only used temporarily and never appear in the query struct so there is no conflict here.

I don't have an overview about all the changes in the PR, but does the assignments blocklist == forwarddestid = -2 still exist. Just asking because of pi-hole/web#1594 (comment)

[Daxtorim]

@DL6ER

it only appeared with you having fixed the first mentioned issue

No, it also happens without my attempted fix. I may have worded that wrong.

ensured that the chosen forward destination is also stored in the database with CNAME, etc. queries

Ah, yes, of course. When changing the upstream DNS server, pihole-FTL will restart and queries have to be read from the database again. If the upstream destination isn't saved for CNAME queries then this information is lost and we obviously can't filter based on it anymore.

fix/querylog_filtering fixes both issues for me 👍

@yubiuser This has nothing to do with the issue you linked. The relevant code for that issue isn't touched by @DL6ER pull request. The actually relevant code still exists:

FTL/src/api/api.c

Lines 524 to 539 in 471fbf7

	for(int i = -2; i < min(counters->upstreams, 8); i++)
	{
	float percentage = 0.0f;
	const char* ip, *name;
	in_port_t upstream_port = 0;
	if(i == -2)
	{
	// Blocked queries (local lists)
	ip = "blocklist";
	name = ip;
	if(totalqueries > 0)
	// Whats the percentage of locked queries on the total amount of queries?
	percentage = 1e2f * counters->blocked / totalqueries;
	}

[yubiuser]

Thanks.

[DL6ER]

Pi-hole v5.5(.1) has been released.