Expected Behaviour:
[All adserver.pandora.com queries should be blocked]
Actual Behaviour:
[1 snuck by]
Debug Token:
[mf8tkbfesv]
How can I diagnose how this happened?
Check the raw dnsmasq log: /var/log/pihole.log
What am I looking for? It's 159,984 lines long...
Do a grep for that time of day. ex: cat /var/log/pihole.log | grep "11:40"
The top of the file reads Aug 10 00:00:13 and counts up, so I don't think the log reaches back far enough.
Then check /var/log/pihole.log.1 (yesterday's log)
Edit: You should be able to see it if you run tail /var/log/pihole.log.1 because it seems to be the last query of that day.
I will when I can, that last command may have frozen up the Pi... still waiting to see if it'll grep it.
edit: it probably wasn't the last query of the day. I searched my query log for "ad" and sorted by URL
I ran "sudo cat /var/log/pihole.log.1 | grep "11:40" and here are the relevant entries:
It doesn't seem to be in the dnsmasq log.
Hm, FTL had to have gotten that time somehow. What if you do less /var/log/pihole.log.1 and type this command: /11:40:37 Enter
Seems to be the same
Check in the Query Log if there's the entry for clients4.google.com at that recorded time. (checking to see if FTL used the wrong domain)
Do you have any suspicions what might have happened? Is this an issue with the current FTL?
I'm now convinced something must be wrong with the Query Log or FTL (I'm not sure how FTL works but Mcat12 gave me the impression it's involved here). How could a user produce all these queries at the exact same second?
The actual list is much longer, but I couldn't fit it. Here are all the queries from 10.139.12.100 at 01:17:27
2017-08-11 01:17:27 IPv4 rad.msn.com 10.139.12.100 Pi-holed Whitelist
2017-08-11 01:17:27 IPv4 c.msn.com 10.139.12.100 Pi-holed Whitelist
2017-08-11 01:17:27 IPv4 rad.msn.com 10.139.12.100 Pi-holed Whitelist
2017-08-11 01:17:27 IPv4 c.msn.com 10.139.12.100 Pi-holed Whitelist
2017-08-11 01:17:27 IPv4 www.bing.com 10.139.12.100 OK (forwarded) Blacklist
2017-08-11 01:17:27 IPv4 www.msn.com 10.139.12.100 OK (forwarded) Blacklist
2017-08-11 01:17:27 IPv4 a-0001.a-msedge.net 10.139.12.100 OK (cached) Blacklist
2017-08-11 01:17:27 IPv4 www.msn.com 10.139.12.100 OK (forwarded) Blacklist
2017-08-11 01:17:27 IPv4 www.myhomemsn.com 10.139.12.100 OK (forwarded) Blacklist
2017-08-11 01:17:27 IPv4 support.microsoft.com 10.139.12.100 OK (cached) Blacklist
2017-08-11 01:17:27 IPv4 outlook.com 10.139.12.100 OK (forwarded) Blacklist
2017-08-11 01:17:27 IPv4 clk.tradedoubler.com 10.139.12.100 Pi-holed Whitelist
2017-08-11 01:17:27 IPv4 clk.tradedoubler.com 10.139.12.100 Pi-holed Whitelist
2017-08-11 01:17:27 IPv4 e3843.g.akamaiedge.net 10.139.12.100 OK (cached) Blacklist
2017-08-11 01:17:27 IPv4 outlook.com 10.139.12.100 OK (cached) Blacklist
2017-08-11 01:17:27 IPv4 www.skype.com 10.139.12.100 OK (forwarded) Blacklist
2017-08-11 01:17:27 IPv4 redirect.viglink.com 10.139.12.100 Pi-holed Whitelist
2017-08-11 01:17:27 IPv4 redirect.viglink.com 10.139.12.100 Pi-holed Whitelist
2017-08-11 01:17:27 IPv4 onedrive.live.com 10.139.12.100 OK (forwarded) Blacklist
2017-08-11 01:17:27 IPv4 bing.com 10.139.12.100 OK (forwarded) Blacklist
2017-08-11 01:17:27 IPv4 livecmseastus.cloudapp.net 10.139.12.100 OK (cached) Blacklist
2017-08-11 01:17:27 IPv4 bing.com 10.139.12.100 OK (cached) Blacklist
2017-08-11 01:17:27 IPv4 a-0014.a-msedge.net 10.139.12.100 OK (cached) Blacklist
2017-08-11 01:17:27 IPv4 www.facebook.com 10.139.12.100 OK (forwarded) Blacklist
2017-08-11 01:17:27 IPv4 static-entertainment-eus-s-msn-com.akamaized.net 10.139.12.100 OK (forwarded)
2017-08-11 01:17:27 IPv4 static-entertainment-eus-s-msn-com.akamaized.net 10.139.12.100 OK (forwarded)
2017-08-11 01:17:27 IPv4 www.onenote.com 10.139.12.100 OK (forwarded) Blacklist
2017-08-11 01:17:27 IPv4 star-mini.c10r.facebook.com 10.139.12.100 OK (cached) Blacklist
2017-08-11 01:17:27 IPv4 twitter.com 10.139.12.100 OK (forwarded) Blacklist
2017-08-11 01:17:27 IPv4 go.microsoft.com 10.139.12.100 OK (forwarded) Blacklist
2017-08-11 01:17:27 IPv4 twitter.com 10.139.12.100 OK (cached) Blacklist
2017-08-11 01:17:27 IPv4 e11290.dspg.akamaiedge.net 10.139.12.100 OK (cached) Blacklist
2017-08-11 01:17:27 IPv4 www.fool.com 10.139.12.100 OK (forwarded) Blacklist
2017-08-11 01:17:27 IPv4 www.autotrader.com 10.139.12.100 OK (forwarded) Blacklist
2017-08-11 01:17:27 IPv4 evcert.motleyfool.map.fastly.net 10.139.12.100 OK (cached) Blacklist
2017-08-11 01:17:27 IPv4 prod-na.reverseproxy-onenote.com.akadns.net 10.139.12.100 OK (cached) Blacklist
2017-08-11 01:17:27 IPv4 zone.msn.com 10.139.12.100 OK (forwarded) Blacklist
2017-08-11 01:17:27 IPv4 www.match.com 10.139.12.100 OK (forwarded) Blacklist
2017-08-11 01:17:27 IPv4 cggameszone.cloudapp.net 10.139.12.100 OK (cached) Blacklist
2017-08-11 01:17:27 IPv4 e8175.a.akamaiedge.net 10.139.12.100 OK (cached) Blacklist
It's perfectly normal for several queries to happen at the same time (a website requests many different domains, the OS batches requests, or just random chance). We're looking into why this might be happening, so it would be helpful if you uploaded the corresponding pihole.log log snippet so we can try to reproduce this.
You want just a chunk of the pihole.log or should I pihole -d? If you want a chunk, please let me know how much of it and a recommendation for the command.
edit: I know that many queries can happen at the same time, but looking at the queries specifically raises some flags for me. For example, I doubt any site is trying to grab information from autotrader.com, facebook.com, and match.com simultaneously, in addition to all the rest.
Thanks
Give a chunk of the query log at a certain time and the corresponding chunk from pihole.log (using grep). The command should look like the one you used previously (either pihole.log or pihole.log.1 depending on the time of the query):
sudo cat /var/log/pihole.log | grep "11:40"
You can send this output to use in the same manner as the debug log is sent:
The amount and variety of those same-second queries is interesting, so we might find that that is a bug as well.
Ummm... it's not showing up in the pihole.log...
I ran sudo cat /var/log/pihole.log | grep "01:17:"
edit: For clarity sake, I wanted to point out that this thread contains 2 similar issues but on 2 different PiHoles at 2 different facilities.
Try finding when the behavior starts and stops in the log and share the chunk in between those times.
I've found another chunk, but looking at the pihole.log seems normal until you see the corresponding query log that doesn't match at all. Here is another instance (I'm not sure how to grep a range of time and what good it would do without the query log):
and here is the rest of the query log for 00:54:08
2017-08-11 00:54:08 IPv4 otf.msn.com 10.139.12.100 Pi-holed Whitelist
2017-08-11 00:54:08 IPv4 otf.msn.com 10.139.12.100 Pi-holed Whitelist
2017-08-11 00:54:08 IPv4 www.myhomemsn.com 10.139.12.100 OK (forwarded) Blacklist
2017-08-11 00:54:08 IPv4 rad.msn.com 10.139.12.100 Pi-holed Whitelist
2017-08-11 00:54:08 IPv4 rad.msn.com 10.139.12.100 Pi-holed Whitelist
2017-08-11 00:54:08 IPv4 support.microsoft.com 10.139.12.100 OK (forwarded) Blacklist
2017-08-11 00:54:08 IPv4 outlook.com 10.139.12.100 OK (forwarded) Blacklist
2017-08-11 00:54:08 IPv4 e3843.g.akamaiedge.net 10.139.12.100 OK (cached) Blacklist
2017-08-11 00:54:08 IPv4 clk.tradedoubler.com 10.139.12.100 Pi-holed Whitelist
2017-08-11 00:54:08 IPv4 clk.tradedoubler.com 10.139.12.100 Pi-holed Whitelist
2017-08-11 00:54:08 IPv4 www.skype.com 10.139.12.100 OK (forwarded) Blacklist
2017-08-11 00:54:08 IPv4 redirect.viglink.com 10.139.12.100 Pi-holed Whitelist
2017-08-11 00:54:08 IPv4 redirect.viglink.com 10.139.12.100 Pi-holed Whitelist
2017-08-11 00:54:08 IPv4 outlook.com 10.139.12.100 OK (cached) Blacklist
2017-08-11 00:54:08 IPv4 onedrive.live.com 10.139.12.100 OK (forwarded) Blacklist
2017-08-11 00:54:08 IPv4 livecmseastus.cloudapp.net 10.139.12.100 OK (cached) Blacklist
2017-08-11 00:54:08 IPv4 www.facebook.com 10.139.12.100 OK (forwarded) Blacklist
2017-08-11 00:54:08 IPv4 a-0014.a-msedge.net 10.139.12.100 OK (cached) Blacklist
2017-08-11 00:54:08 IPv4 www.onenote.com 10.139.12.100 OK (forwarded) Blacklist
2017-08-11 00:54:08 IPv4 star-mini.c10r.facebook.com 10.139.12.100 OK (cached) Blacklist
2017-08-11 00:54:08 IPv4 go.microsoft.com 10.139.12.100 OK (forwarded) Blacklist
2017-08-11 00:54:08 IPv4 e11290.dspg.akamaiedge.net 10.139.12.100 OK (cached) Blacklist
2017-08-11 00:54:08 IPv4 www.fool.com 10.139.12.100 OK (forwarded) Blacklist
2017-08-11 00:54:08 IPv4 www.autotrader.com 10.139.12.100 OK (forwarded) Blacklist
2017-08-11 00:54:08 IPv4 static-entertainment-eus-s-msn-com.akamaized.net 10.139.12.100 OK (forwarded)
2017-08-11 00:54:08 IPv4 static-entertainment-eus-s-msn-com.akamaized.net 10.139.12.100 OK (forwarded)
2017-08-11 00:54:08 IPv4 prod-na.reverseproxy-onenote.com.akadns.net 10.139.12.100 OK (cached) Blacklist
2017-08-11 00:54:08 IPv4 zone.msn.com 10.139.12.100 OK (forwarded) Blacklist
2017-08-11 00:54:08 IPv4 e8175.a.akamaiedge.net 10.139.12.100 OK (cached) Blacklist
2017-08-11 00:54:08 IPv4 www.match.com 10.139.12.100 OK (forwarded) Blacklist
2017-08-11 00:54:08 IPv4 evcert.motleyfool.map.fastly.net 10.139.12.100 OK (cached) Blacklist
2017-08-11 00:54:08 IPv4 flights.msn.com 10.139.12.100 OK (forwarded) Blacklist
edit: the queries in the query log are extremely similar to the previous instance. I've ran MalwareBytes, CCCleaner, and our AV scanner on 10.139.12.100 with nothing out of the ordinary popping up.