Support for add-subnet option from dnsmasq (ECS/EDNS0 Client Subnet)

DL6ER · July 30, 2020, 7:03am

Possible: Yes
Feasible: Absolutely no.

The reason for this is that we added an additional field in the Pi-hole related part of the daemon. The dnsmasq.log is, however, written entirely and solely by the embedded dnsmasq core which is not aware of this EDNS trick. It known only about one client for a query and that is (and has to be) the client which made the request (= is expecting the reply). Changing this would disturb just too much in the code and would cause unpleasant merge issues when future versions of dnsmasq are to be embedded/upgraded.

_FailSafe · July 30, 2020, 11:25am

Understood and I figured this would be the case. Not a big deal at all—just thought I would ask while on this topic.

Thanks!

noahajac · August 9, 2020, 7:56pm

My setup uses dnsdist to forward queries to Pi-hole. Although I'm not doing anything MAC related, I can say that the client subnet recognition is working for me as well.

DL6ER · August 9, 2020, 8:41pm

So you're saying dnsdist attaches EDNS0 Client subnet information as well? Interesting, thanks for sharing this!

noahajac · August 9, 2020, 9:14pm

It does however you have to manually enable it.. For example the block of code that I use to add Pihole is:

setECSOverride(true)
setECSSourcePrefixV4(32)
setECSSourcePrefixV6(128)
newServer({address="127.0.0.1:1026", pool="internal-recursive", checkInterval=60 , useClientSubnet=true})
newServer({address="[::1]:1026", pool="internal-recursive", checkInterval=60, useClientSubnet=true})

Thanks for your hard work! I've been using Pihole for at least a year at this point and it makes browsing the web so much nicer.

DL6ER · August 10, 2020, 9:12pm

See

github.com/pi-hole/FTL

Analyze EDNS(0) records

pi-hole:development ← pi-hole:new/edns0

opened 06:48PM - 21 Jul 20 UTC

DL6ER

+563 -71

**By submitting this pull request, I confirm the following:** - [X] I have re…ad and understood the [contributors guide](https://github.com/pi-hole/pi-hole/blob/master/CONTRIBUTING.md). - [X] I have checked that [another pull request](https://github.com/pi-hole/FTL/pulls) for this purpose does not exist. - [X] I have considered, and confirmed that this submission will be valuable to others. - [X] I accept that this submission may not be used, and the pull request closed at the will of the maintainer. - [X] I give this submission freely, and claim no ownership to its content. **How familiar are you with the codebase?:** ## 10 --- Analyze EDNS(0) records. We are especially interested in the Client Subnet feature to obtain client IPs even if they are hidden behind the NAT of a router. See the referenced Discourse discussion for further (technical) details.

for the progress on getting this merged for the next version of Pi-hole FTL.

yubiuser · August 16, 2020, 8:34pm

I configured my router/primary DNS server to use add-mac and add-subnet=32 (running dnsmasq). I've got some clients on a different subnet than my pihole. I can see pihole recieving EDNS information

[2020-08-16 22:26:16.517 22669M] EDNS(0) pheader[0] = 0x00
[2020-08-16 22:26:16.518 22669M] EDNS(0) pheader[1] = 0x00
[2020-08-16 22:26:16.518 22669M] EDNS(0) pheader[2] = 0x29
[2020-08-16 22:26:16.518 22669M] EDNS(0) pheader[3] = 0x02
[2020-08-16 22:26:16.518 22669M] EDNS(0) pheader[4] = 0x00
[2020-08-16 22:26:16.518 22669M] EDNS(0) pheader[5] = 0x00
[2020-08-16 22:26:16.518 22669M] EDNS(0) pheader[6] = 0x00
[2020-08-16 22:26:16.519 22669M] EDNS(0) pheader[7] = 0x00
[2020-08-16 22:26:16.519 22669M] EDNS(0) pheader[8] = 0x00
[2020-08-16 22:26:16.519 22669M] EDNS(0) pheader[9] = 0x00
[2020-08-16 22:26:16.519 22669M] EDNS(0) pheader[10] = 0x16
[2020-08-16 22:26:16.519 22669M] EDNS(0) pheader[11] = 0xfd
[2020-08-16 22:26:16.519 22669M] EDNS(0) pheader[12] = 0xe9
[2020-08-16 22:26:16.519 22669M] EDNS(0) pheader[13] = 0x00
[2020-08-16 22:26:16.519 22669M] EDNS(0) pheader[14] = 0x06
[2020-08-16 22:26:16.519 22669M] EDNS(0) pheader[15] = 0x00
[2020-08-16 22:26:16.520 22669M] EDNS(0) pheader[16] = 0x25
[2020-08-16 22:26:16.520 22669M] EDNS(0) pheader[17] = 0xd3
[2020-08-16 22:26:16.520 22669M] EDNS(0) pheader[18] = 0xc4
[2020-08-16 22:26:16.520 22669M] EDNS(0) pheader[19] = 0xd6
[2020-08-16 22:26:16.520 22669M] EDNS(0) pheader[20] = 0xa4
[2020-08-16 22:26:16.520 22669M] EDNS(0) pheader[21] = 0x00
[2020-08-16 22:26:16.520 22669M] EDNS(0) pheader[22] = 0x08
[2020-08-16 22:26:16.520 22669M] EDNS(0) pheader[23] = 0x00
[2020-08-16 22:26:16.521 22669M] EDNS(0) pheader[24] = 0x08
[2020-08-16 22:26:16.521 22669M] EDNS(0) pheader[25] = 0x00
[2020-08-16 22:26:16.521 22669M] EDNS(0) pheader[26] = 0x01
[2020-08-16 22:26:16.521 22669M] EDNS(0) pheader[27] = 0x20
[2020-08-16 22:26:16.521 22669M] EDNS(0) pheader[28] = 0x00
[2020-08-16 22:26:16.521 22669M] EDNS(0) pheader[29] = 0x0a
[2020-08-16 22:26:16.521 22669M] EDNS(0) pheader[30] = 0x00
[2020-08-16 22:26:16.521 22669M] EDNS(0) pheader[31] = 0x0a
[2020-08-16 22:26:16.521 22669M] EDNS(0) pheader[32] = 0x54
[2020-08-16 22:26:16.521 22669M] EDNS(0) requestor's UDP payload size: 512 bytes
[2020-08-16 22:26:16.522 22669M] EDNS(0) code 65001, optlen 6 (bytes 4 - 10 of 22)
[2020-08-16 22:26:16.522 22669M] EDNS(0) MAC address (BYTE format): 00:25:d3:c4:d6:a4
[2020-08-16 22:26:16.522 22669M] EDNS(0) code 8, optlen 8 (bytes 14 - 22 of 22)
[2020-08-16 22:26:16.522 22669M] EDNS(0) CLIENT SUBNET: 10.0.10.84/32

But the client's MAC does not show up in Tools/Network (table). Shouldn't it be there?

DL6ER · August 16, 2020, 9:14pm

There were some things still to be added (which were, on the other hand, already implemented elsewhere), so I refrained from making this live for FTL v5.2. It is now available under the latest version of new/mac_clients (remember that switching back from new/mac_clients to master can only be done by deleting the network and network_addresses tables).

Thank you for testing, I was only able to test this using local mock-EDNS(0) datagrams as my routers do not run dnsmasq instances. It will be interesting to see if this performs well in a live setup.

yubiuser · August 17, 2020, 8:51am

nanopi@nanopi:~$ pihole -v
  Pi-hole version is new/adlist_date_updated v5.0-119-gdcafdc2 (Latest: v5.1.2)
  AdminLTE version is new/mac_clients v5.1-36-g1b129bca (Latest: v5.1.1)
  FTL version is new/mac_clients vDev-1a6e083 (Latest: v5.2)

It's not working for me. I have it running since yesterday evening.

[2020-08-17 10:49:22.580 28507M] EDNS(0) requestor's UDP payload size: 512 bytes
[2020-08-17 10:49:22.581 28507M] EDNS(0) code 65001, optlen 6 (bytes 4 - 10 of 22)
[2020-08-17 10:49:22.581 28507M] EDNS(0) MAC address (BYTE format): d4:38:9c:01:ac:6c
[2020-08-17 10:49:22.581 28507M] EDNS(0) code 8, optlen 8 (bytes 14 - 22 of 22)
[2020-08-17 10:49:22.581 28507M] EDNS(0) CLIENT SUBNET: 10.0.10.190/32

Coro · August 17, 2020, 9:41am

Enable DEBUG_DATABASE=true and reload FTL. Try to find what FTL does with your client, especially if it write something like this into its log (and what is the outcome?):

SELECT id FROM network WHERE hwaddr = 'd4:38:9c:01:ac:6c' COLLATE NOCASE;
(where I got this from)

yubiuser · August 17, 2020, 11:00am

Good idea.

[2020-08-17 12:03:12.930 21041M] EDNS(0) requestor's UDP payload size: 512 bytes
[2020-08-17 12:03:12.931 21041M] EDNS(0) code 65001, optlen 6 (bytes 4 - 10 of 22)
[2020-08-17 12:03:12.931 21041M] EDNS(0) MAC address (BYTE format): d4:38:9c:01:ac:6c
[2020-08-17 12:03:12.931 21041M] EDNS(0) code 8, optlen 8 (bytes 14 - 22 of 22)
[2020-08-17 12:03:12.931 21041M] EDNS(0) CLIENT SUBNET: 10.0.10.190/32
[2020-08-17 12:03:12.931 21041M] Finalizing gravity statements for 10.0.10.190
[2020-08-17 12:03:12.931 21041M] Initializing gravity statements for 10.0.10.190
[2020-08-17 12:03:12.932 21041M] A
[2020-08-17 12:03:12.932 21041M] SQL: Comparing 10.0.10.190 vs. 10.0.1.0/16 (subnet 255.255.0.0) - !! MATCH !!
[2020-08-17 12:03:12.933 21041M] SQL: Comparing 10.0.10.190 vs. 10.0.1.0/16 (subnet 255.255.0.0) - !! MATCH !!
[2020-08-17 12:03:12.933 21041M] SQL: Comparing 10.0.10.190 vs. 10.0.10.1/24 (subnet 255.255.255.0) - !! MATCH !!
[2020-08-17 12:03:12.933 21041M] SQL: Comparing 10.0.10.190 vs. 10.0.10.1/24 (subnet 255.255.255.0) - !! MATCH !!
[2020-08-17 12:03:12.933 21041M] SQL: Comparing 10.0.10.190 vs. 10.0.10.1/24 (subnet 255.255.255.0) - !! MATCH !!
[2020-08-17 12:03:12.934 21041M] gravityDB_open(): Preparing vw_whitelist statement for client 10.0.10.190
[2020-08-17 12:03:12.934 21041M] get_client_querystr: SELECT EXISTS(SELECT domain from vw_whitelist WHERE domain = ? AND group_id IN (0));
[2020-08-17 12:03:12.934 21041M] gravityDB_open(): Preparing vw_gravity statement for client 10.0.10.190
[2020-08-17 12:03:12.934 21041M] get_client_querystr: SELECT EXISTS(SELECT domain from vw_gravity WHERE domain = ? AND group_id IN (0));
[2020-08-17 12:03:12.935 21041M] gravityDB_open(): Preparing vw_blacklist statement for client 10.0.10.190
[2020-08-17 12:03:12.935 21041M] get_client_querystr: SELECT EXISTS(SELECT domain from vw_blacklist WHERE domain = ? AND gr


[...]

[2020-08-17 12:04:00.153 21041/T21045] dbquery: "SELECT id FROM network WHERE hwaddr = 'D4:38:9C:01:AC:6C' COLLATE NOCASE;"
[2020-08-17 12:04:00.153 21041/T21045]          ---> No data
[2020-08-17 12:04:00.153 21041/T21045] dbquery: "SELECT network_id FROM network_addresses WHERE ip = '10.0.10.190' AND lastSeen > (cast(strftime('%s', 'now') as int)-86400) ORDER BY lastSeen DESC LIMIT 1;"
[2020-08-17 12:04:00.153 21041/T21045]          ---> Result 11 (int)
[2020-08-17 12:04:00.153 21041/T21045] dbquery: "UPDATE network SET lastQuery = MAX(lastQuery, 1597658607) WHERE id = 11;"
[2020-08-17 12:04:00.154 21041/T21045]          ---> OK
[2020-08-17 12:04:00.154 21041/T21045] dbquery: "UPDATE network SET numQueries = numQueries + 2 WHERE id = 11;"
[2020-08-17 12:04:00.154 21041/T21045]          ---> OK
[2020-08-17 12:04:00.154 21041/T21045] dbquery: "INSERT OR REPLACE INTO network_addresses (network_id,ip,lastSeen,name,nameUpdated) VALUES (?1,?2,(cast(strftime('%s', 'now') as int)),(SELECT name FROM network_addresses WHERE ip = ?2),(SELECT nameUpdated FROM network_addresses WHERE ip = ?2));" with arguments ?1 = 11 and ?2 = "10.0.10.190"
[2020-08-17 12:04:00.154 21041/T21045] dbquery: "UPDATE network_addresses SET name = ?1, nameUpdated = (cast(strftime('%s', 'now') as int)) WHERE ip = ?2" with arguments 1 = "sony-xz1-compact" and 2 = "10.0.10.190"
[2020-08-17 12:04:00.154 21041/T21045] dbquery: "UPDATE network SET interface = ?1 WHERE id = ?2" with arguments ?1 = "eth0" and ?2 = 11

I've also noticed (with only DEBUG_EDNS0=true some lines containing only

[2020-08-17 12:47:30.929 21041M] A

DL6ER · August 17, 2020, 6:05pm

Thanks @Coro for nice debugging hints, we see now what is happening:

FTL tries to find a client with the given EDNS(0) provided MAC address
---> There is none
FTL tries to find another device with the given IP that was active recently
---> There IS one (the old mock-device)

As there is no such client and FTL found the client which recently received the counts for this device (the device with the id 11), FTL continues to attribute the counts to this client.

I can see that there may be a need to, instead of attributing this still to the mock-client, create a new client record here. I just changed the logic to reflect this. @yubiuser please try it.

Removed this as well, thanks. I already removed this in other branches and wasn't aware that this is still here.

yubiuser · August 17, 2020, 6:18pm

Confirm working. (Had to flush network table once to remove some empty - N/A - unknown clients, probably leftovers)

Bildschirmfoto zu 2020-08-17 20-16-48

yubiuser · August 17, 2020, 7:13pm

One client popped up I don't know and can't identify

DL6ER · August 17, 2020, 7:36pm

What are the database related log lines around 20:15:00 ?

edit I just added more debug output which will make clear why a certain decision was made by FTL. They are all prefixed by Network table: to make greping for them easier. Make sure DEBUG_ARP is set to true as well.

yubiuser · August 18, 2020, 12:36pm

[2020-08-17 20:14:58.350 6047/F5457] gravityDB_open(): Successfully opened gravity.db
[2020-08-17 20:14:58.350 6047/F5457] TCP worker terminating (client disconnected)
[2020-08-17 20:14:58.350 6047/F5457] Finalizing gravity statements for 10.0.10.182
[2020-08-17 20:14:58.350 6047/F5457] Finalizing gravity statements for 10.0.1.1
[2020-08-17 20:14:58.350 6047/F5457] Finalizing gravity statements for 10.0.40.3
[2020-08-17 20:14:58.350 6047/F5457] Finalizing gravity statements for 10.0.10.190
[2020-08-17 20:14:58.350 6047/F5457] Finalizing gravity statements for 10.0.10.215
[2020-08-17 20:14:58.350 6047/F5457] Finalizing gravity statements for 10.0.1.7
[2020-08-17 20:14:58.351 6047/F5457] Finalizing gravity statements for 10.0.1.2
[2020-08-17 20:14:58.351 6047/F5457] Finalizing gravity statements for 127.0.0.1
[2020-08-17 20:14:58.351 6047/F5457] Finalizing gravity statements for 10.0.10.64
[2020-08-17 20:14:58.351 6047/F5457] Finalizing gravity statements for 10.0.10.84
[2020-08-17 20:15:00.003 5457/T5461] dbquery: "BEGIN TRANSACTION IMMEDIATE"
[2020-08-17 20:15:00.003 5457/T5461]          ---> OK
[2020-08-17 20:15:00.004 5457/T5461] dbquery: "SELECT MAX(ID) FROM queries"
[2020-08-17 20:15:00.005 5457/T5461]          ---> Result 1137954 (long long int)
[2020-08-17 20:15:00.009 5457/T5461] dbquery: "END TRANSACTION"
[2020-08-17 20:15:00.022 5457/T5461]          ---> OK
[2020-08-17 20:15:00.022 5457/T5461] dbquery: "INSERT OR REPLACE INTO ftl (id, value) VALUES ( 1, 1597688097 );"
[2020-08-17 20:15:00.028 5457/T5461]          ---> OK
[2020-08-17 20:15:00.028 5457/T5461] dbquery: "UPDATE counters SET value = value + 66 WHERE id = 0;"
[2020-08-17 20:15:00.037 5457/T5461]          ---> OK
[2020-08-17 20:15:00.037 5457/T5461] dbquery: "UPDATE counters SET value = value + 30 WHERE id = 1;"
[2020-08-17 20:15:00.043 5457/T5461]          ---> OK
[2020-08-17 20:15:00.044 5457/T5461] Notice: Queries stored in long-term database: 66 (took 16.8 ms, last SQLite ID 1138020)
[2020-08-17 20:15:00.045 5457/T5461] dbquery: "BEGIN TRANSACTION IMMEDIATE"
[2020-08-17 20:15:00.046 5457/T5461]          ---> OK
[2020-08-17 20:15:00.056 5457/T5461] dbquery: "SELECT id FROM network WHERE hwaddr = 'f0:9f:c2:1e:8f:e9';"
[2020-08-17 20:15:00.057 5457/T5461]          ---> No data
[2020-08-17 20:15:00.058 5457/T5461] dbquery: "SELECT id FROM network WHERE hwaddr = 'ip-10.0.1.1' AND firstSeen > (cast(strftime('%s', 'now') as int)-3600);"
[2020-08-17 20:15:00.058 5457/T5461]          ---> No data
[2020-08-17 20:15:00.094 5457/T5461] DEBUG: MAC Vendor lookup for f0:9f:c2:1e:8f:e9 returned "Ubiquiti Networks Inc."
[2020-08-17 20:15:00.094 5457/T5461] dbquery: "INSERT INTO network (hwaddr,interface,firstSeen,lastQuery,numQueries,macVendor) VALUES (?1,'N/A',?2,?3,?4,?5);" with arguments ?1-?5 = ("f0:9f:c2:1e:8f:e9",1597688100,1597609573,0,"Ubiquiti Networks Inc.")
[2020-08-17 20:15:00.095 5457/T5461] dbquery: "INSERT OR REPLACE INTO network_addresses (network_id,ip,lastSeen,name,nameUpdated) VALUES (?1,?2,(cast(strftime('%s', 'now') as int)),(SELECT name FROM network_addresses WHERE ip = ?2),(SELECT nameUpdated FROM network_addresses WHERE ip = ?2));" with arguments ?1 = 1 and ?2 = "10.0.1.1"
[2020-08-17 20:15:00.095 5457/T5461] dbquery: "UPDATE network_addresses SET name = ?1, nameUpdated = (cast(strftime('%s', 'now') as int)) WHERE ip = ?2" with arguments 1 = "usg" and 2 = "10.0.1.1"
[2020-08-17 20:15:00.095 5457/T5461] dbquery: "UPDATE network SET interface = ?1 WHERE id = ?2" with arguments ?1 = "eth0" and ?2 = 1
[2020-08-17 20:15:00.096 5457/T5461] dbquery: "INSERT OR REPLACE INTO network_addresses (network_id,ip,lastSeen,name,nameUpdated) VALUES (?1,?2,(cast(strftime('%s', 'now') as int)),(SELECT name FROM network_addresses WHERE ip = ?2),(SELECT nameUpdated FROM network_addresses WHERE ip = ?2));" with arguments ?1 = 1 and ?2 = "10.0.1.1"
[2020-08-17 20:15:00.096 5457/T5461] dbquery: "SELECT id FROM network WHERE hwaddr = 'e0:63:da:2c:19:17';"
[2020-08-17 20:15:00.096 5457/T5461]          ---> No data
[2020-08-17 20:15:00.096 5457/T5461] dbquery: "SELECT id FROM network WHERE hwaddr = 'ip-10.0.1.2' AND firstSeen > (cast(strftime('%s', 'now') as int)-3600);"
[2020-08-17 20:15:00.096 5457/T5461]          ---> No data
[2020-08-17 20:15:00.127 5457/T5461] DEBUG: MAC Vendor lookup for e0:63:da:2c:19:17 returned "Ubiquiti Networks Inc."
[2020-08-17 20:15:00.127 5457/T5461] dbquery: "INSERT INTO network (hwaddr,interface,firstSeen,lastQuery,numQueries,macVendor) VALUES (?1,'N/A',?2,?3,?4,?5);" with arguments ?1-?5 = ("e0:63:da:2c:19:17",1597688100,1597685972,0,"Ubiquiti Networks Inc.")
[2020-08-17 20:15:00.128 5457/T5461] dbquery: "INSERT OR REPLACE INTO network_addresses (network_id,ip,lastSeen,name,nameUpdated) VALUES (?1,?2,(cast(strftime('%s', 'now') as int)),(SELECT name FROM network_addresses WHERE ip = ?2),(SELECT nameUpdated FROM network_addresses WHERE ip = ?2));" with arguments ?1 = 2 and ?2 = "10.0.1.2"
[2020-08-17 20:15:00.128 5457/T5461] dbquery: "UPDATE network_addresses SET name = ?1, nameUpdated = (cast(strftime('%s', 'now') as int)) WHERE ip = ?2" with arguments 1 = "cloudkey" and 2 = "10.0.1.2"
[2020-08-17 20:15:00.128 5457/T5461] dbquery: "UPDATE network SET interface = ?1 WHERE id = ?2" with arguments ?1 = "eth0" and ?2 = 2
[2020-08-17 20:15:00.128 5457/T5461] dbquery: "INSERT OR REPLACE INTO network_addresses (network_id,ip,lastSeen,name,nameUpdated) VALUES (?1,?2,(cast(strftime('%s', 'now') as int)),(SELECT name FROM network_addresses WHERE ip = ?2),(SELECT nameUpdated FROM network_addresses WHERE ip = ?2));" with arguments ?1 = 2 and ?2 = "10.0.1.2"
[2020-08-17 20:15:00.128 5457/T5461] dbquery: "SELECT id FROM network WHERE hwaddr = '00:a2:89:5b:1d:f0';"
[2020-08-17 20:15:00.129 5457/T5461]          ---> No data
[2020-08-17 20:15:00.129 5457/T5461] dbquery: "SELECT id FROM network WHERE hwaddr = 'ip-10.0.1.7' AND firstSeen > (cast(strftime('%s', 'now') as int)-3600);"
[2020-08-17 20:15:00.129 5457/T5461]          ---> No data
[2020-08-17 20:15:00.143 5457/T5461] DEBUG: MAC Vendor lookup for 00:a2:89:5b:1d:f0 returned "Cisco Systems, Inc"
[2020-08-17 20:15:00.143 5457/T5461] dbquery: "INSERT INTO network (hwaddr,interface,firstSeen,lastQuery,numQueries,macVendor) VALUES (?1,'N/A',?2,?3,?4,?5);" with arguments ?1-?5 = ("00:a2:89:5b:1d:f0",1597688100,1597687812,0,"Cisco Systems, Inc")
[2020-08-17 20:15:00.144 5457/T5461] dbquery: "INSERT OR REPLACE INTO network_addresses (network_id,ip,lastSeen,name,nameUpdated) VALUES (?1,?2,(cast(strftime('%s', 'now') as int)),(SELECT name FROM network_addresses WHERE ip = ?2),(SELECT nameUpdated FROM network_addresses WHERE ip = ?2));" with arguments ?1 = 3 and ?2 = "10.0.1.7"
[2020-08-17 20:15:00.144 5457/T5461] dbquery: "UPDATE network_addresses SET name = ?1, nameUpdated = (cast(strftime('%s', 'now') as int)) WHERE ip = ?2" with arguments 1 = "spa112" and 2 = "10.0.1.7"
[2020-08-17 20:15:00.144 5457/T5461] dbquery: "UPDATE network SET interface = ?1 WHERE id = ?2" with arguments ?1 = "eth0" and ?2 = 3
[2020-08-17 20:15:00.144 5457/T5461] dbquery: "INSERT OR REPLACE INTO network_addresses (network_id,ip,lastSeen,name,nameUpdated) VALUES (?1,?2,(cast(strftime('%s', 'now') as int)),(SELECT name FROM network_addresses WHERE ip = ?2),(SELECT nameUpdated FROM network_addresses WHERE ip = ?2));" with arguments ?1 = 3 and ?2 = "10.0.1.7"
[2020-08-17 20:15:00.144 5457/T5461] dbquery: "SELECT id FROM network WHERE hwaddr = 'f0:9f:c2:ce:09:31';"
[2020-08-17 20:15:00.144 5457/T5461]          ---> No data
[2020-08-17 20:15:00.144 5457/T5461] dbquery: "SELECT id FROM network WHERE hwaddr = 'ip-10.0.1.3' AND firstSeen > (cast(strftime('%s', 'now') as int)-3600);"
[2020-08-17 20:15:00.145 5457/T5461]          ---> No data
[2020-08-17 20:15:00.177 5457/T5461] DEBUG: MAC Vendor lookup for f0:9f:c2:ce:09:31 returned "Ubiquiti Networks Inc."
[2020-08-17 20:15:00.177 5457/T5461] dbquery: "INSERT INTO network (hwaddr,interface,firstSeen,lastQuery,numQueries,macVendor) VALUES (?1,'N/A',?2,?3,?4,?5);" with arguments ?1-?5 = ("f0:9f:c2:ce:09:31",1597688100,0,0,"Ubiquiti Networks Inc.")
[2020-08-17 20:15:00.177 5457/T5461] dbquery: "INSERT OR REPLACE INTO network_addresses (network_id,ip,lastSeen,name,nameUpdated) VALUES (?1,?2,(cast(strftime('%s', 'now') as int)),(SELECT name FROM network_addresses WHERE ip = ?2),(SELECT nameUpdated FROM network_addresses WHERE ip = ?2));" with arguments ?1 = 4 and ?2 = "10.0.1.3"
[2020-08-17 20:15:05.209 5457/T5461] dbquery: "UPDATE network SET interface = ?1 WHERE id = ?2" with arguments ?1 = "eth0" and ?2 = 4
[2020-08-17 20:15:05.209 5457/T5461] dbquery: "INSERT OR REPLACE INTO network_addresses (network_id,ip,lastSeen,name,nameUpdated) VALUES (?1,?2,(cast(strftime('%s', 'now') as int)),(SELECT name FROM network_addresses WHERE ip = ?2),(SELECT nameUpdated FROM network_addresses WHERE ip = ?2));" with arguments ?1 = 4 and ?2 = "10.0.1.3"
[2020-08-17 20:15:05.210 5457/T5461] dbquery: "SELECT id FROM network WHERE hwaddr = 'f0:9f:c2:dc:2f:75';"
[2020-08-17 20:15:05.210 5457/T5461]          ---> No data
[2020-08-17 20:15:05.210 5457/T5461] dbquery: "SELECT id FROM network WHERE hwaddr = 'ip-10.0.1.4' AND firstSeen > (cast(strftime('%s', 'now') as int)-3600);"
[2020-08-17 20:15:05.210 5457/T5461]          ---> No data
[2020-08-17 20:15:05.257 5457/T5461] DEBUG: MAC Vendor lookup for f0:9f:c2:dc:2f:75 returned "Ubiquiti Networks Inc."
[2020-08-17 20:15:05.258 5457/T5461] dbquery: "INSERT INTO network (hwaddr,interface,firstSeen,lastQuery,numQueries,macVendor) VALUES (?1,'N/A',?2,?3,?4,?5);" with arguments ?1-?5 = ("f0:9f:c2:dc:2f:75",1597688100,0,0,"Ubiquiti Networks Inc.")
[2020-08-17 20:15:05.258 5457/T5461] dbquery: "INSERT OR REPLACE INTO network_addresses (network_id,ip,lastSeen,name,nameUpdated) VALUES (?1,?2,(cast(strftime('%s', 'now') as int)),(SELECT name FROM network_addresses WHERE ip = ?2),(SELECT nameUpdated FROM network_addresses WHERE ip = ?2));" with arguments ?1 = 5 and ?2 = "10.0.1.4"
[2020-08-17 20:15:15.272 5457/T5461] dbquery: "UPDATE network SET interface = ?1 WHERE id = ?2" with arguments ?1 = "eth0" and ?2 = 5
[2020-08-17 20:15:15.273 5457/T5461] dbquery: "INSERT OR REPLACE INTO network_addresses (network_id,ip,lastSeen,name,nameUpdated) VALUES (?1,?2,(cast(strftime('%s', 'now') as int)),(SELECT name FROM network_addresses WHERE ip = ?2),(SELECT nameUpdated FROM network_addresses WHERE ip = ?2));" with arguments ?1 = 5 and ?2 = "10.0.1.4"
[2020-08-17 20:15:15.273 5457/T5461] dbquery: "SELECT network_id FROM network_addresses WHERE ip = '10.0.10.182' AND lastSeen > (cast(strftime('%s', 'now') as int)-86400) ORDER BY lastSeen DESC LIMIT 1;"
[2020-08-17 20:15:15.273 5457/T5461]          ---> No data
[2020-08-17 20:15:15.273 5457/T5461] dbquery: "SELECT id FROM network WHERE hwaddr = 'ip-10.0.10.182';"
[2020-08-17 20:15:15.274 5457/T5461]          ---> No data
[2020-08-17 20:15:15.274 5457/T5461] dbquery: "INSERT INTO network (hwaddr,interface,firstSeen,lastQuery,numQueries,macVendor) VALUES (?1,'N/A',?2,?3,?4,?5);" with arguments ?1-?5 = ("ip-10.0.10.182",1597688100,1597688082,8,"(null)")
[2020-08-17 20:15:15.274 5457/T5461] dbquery: "INSERT OR REPLACE INTO network_addresses (network_id,ip,lastSeen,name,nameUpdated) VALUES (?1,?2,(cast(strftime('%s', 'now') as int)),(SELECT name FROM network_addresses WHERE ip = ?2),(SELECT nameUpdated FROM network_addresses WHERE ip = ?2));" with arguments ?1 = 6 and ?2 = "10.0.10.182"
[2020-08-17 20:15:15.275 5457/T5461] dbquery: "UPDATE network_addresses SET name = ?1, nameUpdated = (cast(strftime('%s', 'now') as int)) WHERE ip = ?2" with arguments 1 = "thinkpad-wifi" and 2 = "10.0.10.182"
[2020-08-17 20:15:15.275 5457/T5461] dbquery: "UPDATE network SET interface = ?1 WHERE id = ?2" with arguments ?1 = "eth0" and ?2 = 6
[2020-08-17 20:15:15.275 5457/T5461] dbquery: "SELECT network_id FROM network_addresses WHERE ip = '127.0.0.1' AND lastSeen > (cast(strftime('%s', 'now') as int)-86400) ORDER BY lastSeen DESC LIMIT 1;"
[2020-08-17 20:15:15.275 5457/T5461]          ---> No data
[2020-08-17 20:15:15.275 5457/T5461] dbquery: "SELECT id FROM network WHERE hwaddr = 'ip-127.0.0.1';"
[2020-08-17 20:15:15.275 5457/T5461]          ---> No data
[2020-08-17 20:15:15.276 5457/T5461] dbquery: "INSERT INTO network (hwaddr,interface,firstSeen,lastQuery,numQueries,macVendor) VALUES (?1,'N/A',?2,?3,?4,?5);" with arguments ?1-?5 = ("ip-127.0.0.1",1597688100,1597688095,1,"(null)")
[2020-08-17 20:15:15.276 5457/T5461] dbquery: "INSERT OR REPLACE INTO network_addresses (network_id,ip,lastSeen,name,nameUpdated) VALUES (?1,?2,(cast(strftime('%s', 'now') as int)),(SELECT name FROM network_addresses WHERE ip = ?2),(SELECT nameUpdated FROM network_addresses WHERE ip = ?2));" with arguments ?1 = 7 and ?2 = "127.0.0.1"
[2020-08-17 20:15:15.276 5457/T5461] dbquery: "UPDATE network_addresses SET name = ?1, nameUpdated = (cast(strftime('%s', 'now') as int)) WHERE ip = ?2" with arguments 1 = "localhost" and 2 = "127.0.0.1"
[2020-08-17 20:15:15.277 5457/T5461] dbquery: "UPDATE network SET interface = ?1 WHERE id = ?2" with arguments ?1 = "lo" and ?2 = 7
[2020-08-17 20:15:15.277 5457/T5461] dbquery: "SELECT id FROM network WHERE hwaddr = '14:20:5E:DB:00:16' COLLATE NOCASE;"
[2020-08-17 20:15:15.277 5457/T5461]          ---> No data
[2020-08-17 20:15:15.303 5457/T5461] DEBUG: MAC Vendor lookup for 14:20:5E:DB:00:16 returned "Apple, Inc."
[2020-08-17 20:15:15.303 5457/T5461] dbquery: "INSERT INTO network (hwaddr,interface,firstSeen,lastQuery,numQueries,macVendor) VALUES (?1,'N/A',?2,?3,?4,?5);" with arguments ?1-?5 = ("14:20:5E:DB:00:16",1597688100,1597688097,57,"Apple, Inc.")
[2020-08-17 20:15:15.304 5457/T5461] dbquery: "INSERT OR REPLACE INTO network_addresses (network_id,ip,lastSeen,name,nameUpdated) VALUES (?1,?2,(cast(strftime('%s', 'now') as int)),(SELECT name FROM network_addresses WHERE ip = ?2),(SELECT nameUpdated FROM network_addresses WHERE ip = ?2));" with arguments ?1 = 8 and ?2 = "10.0.10.64"
[2020-08-17 20:15:15.304 5457/T5461] dbquery: "UPDATE network_addresses SET name = ?1, nameUpdated = (cast(strftime('%s', 'now') as int)) WHERE ip = ?2" with arguments 1 = "ipad" and 2 = "10.0.10.64"
[2020-08-17 20:15:15.304 5457/T5461] dbquery: "UPDATE network SET interface = ?1 WHERE id = ?2" with arguments ?1 = "eth0" and ?2 = 8
[2020-08-17 20:15:15.304 5457/T5461] dbquery: "END TRANSACTION"
[2020-08-17 20:15:15.314 5457/T5461]          ---> OK
[2020-08-17 20:15:15.315 5457M] Finalizing gravity statements for 127.0.0.1
[2020-08-17 20:15:15.315 5457M] Initializing gravity statements for 127.0.0.1
[2020-08-17 20:15:15.316 5457M] SQL: Comparing 127.0.0.1 vs. 10.0.1.0/16 (subnet 255.255.0.0) - NO MATCH
[2020-08-17 20:15:15.316 5457M] SQL: Comparing 127.0.0.1 vs. 10.0.10.1/24 (subnet 255.255.255.0) - NO MATCH
[2020-08-17 20:15:15.317 5457M] Found database hardware address 127.0.0.1 -> ip-127.0.0.1
[2020-08-17 20:15:15.317 5457M] Skipping mock-device hardware address lookup
[2020-08-17 20:15:15.318 5457M] Found database host name 127.0.0.1 -> localhost
[2020-08-17 20:15:15.325 5457M] Found database interface 127.0.0.1 -> lo
[2020-08-17 20:15:15.325 5457M] gravityDB_open(): Preparing vw_whitelist statement for client 127.0.0.1
[2020-08-17 20:15:15.325 5457M] get_client_querystr: SELECT EXISTS(SELECT domain from vw_whitelist WHERE domain = ? AND group_id IN (0));
[2020-08-17 20:15:15.326 5457M] gravityDB_open(): Preparing vw_gravity statement for client 127.0.0.1
[2020-08-17 20:15:15.326 5457M] get_client_querystr: SELECT EXISTS(SELECT domain from vw_gravity WHERE domain = ? AND group_id IN (0));
[2020-08-17 20:15:15.326 5457M] gravityDB_open(): Preparing vw_blacklist statement for client 127.0.0.1
[2020-08-17 20:15:15.326 5457M] get_client_querystr: SELECT EXISTS(SELECT domain from vw_blacklist WHERE domain = ? AND group_id IN (0));
[2020-08-17 20:15:15.327 5457M] domain_in_list("3.1.0.10.in-addr.arpa", 0xaaab0f22b9d8, whitelist): 0
[2020-08-17 20:15:15.327 5457M] Finalizing gravity statements for 127.0.0.1
[2020-08-17 20:15:15.328 5457M] Initializing gravity statements for 127.0.0.1
[2020-08-17 20:15:15.328 5457M] SQL: Comparing 127.0.0.1 vs. 10.0.1.0/16 (subnet 255.255.0.0) - NO MATCH
[2020-08-17 20:15:15.328 5457M] SQL: Comparing 127.0.0.1 vs. 10.0.10.1/24 (subnet 255.255.255.0) - NO MATCH
[2020-08-17 20:15:15.329 5457M] Found database hardware address 127.0.0.1 -> ip-127.0.0.1
[2020-08-17 20:15:15.329 5457M] Skipping mock-device hardware address lookup
[2020-08-17 20:15:15.330 5457M] Found database host name 127.0.0.1 -> localhost
[2020-08-17 20:15:15.332 5457M] Found database interface 127.0.0.1 -> lo
[2020-08-17 20:15:15.332 5457M] gravityDB_open(): Preparing vw_whitelist statement for client 127.0.0.1
[2020-08-17 20:15:15.332 5457M] get_client_querystr: SELECT EXISTS(SELECT domain from vw_whitelist WHERE domain = ? AND group_id IN (0));
[2020-08-17 20:15:15.332 5457M] gravityDB_open(): Preparing vw_gravity statement for client 127.0.0.1
[2020-08-17 20:15:15.333 5457M] get_client_querystr: SELECT EXISTS(SELECT domain from vw_gravity WHERE domain = ? AND group_id IN (0));
[2020-08-17 20:15:15.333 5457M] gravityDB_open(): Preparing vw_blacklist statement for client 127.0.0.1
[2020-08-17 20:15:15.333 5457M] get_client_querystr: SELECT EXISTS(SELECT domain from vw_blacklist WHERE domain = ? AND group_id IN (0));
[2020-08-17 20:15:15.334 5457M] domain_in_list("3.1.0.10.in-addr.arpa", 0xaaab0f22ed68, blacklist): 0
[2020-08-17 20:15:15.334 5457M] domain_in_list("3.1.0.10.in-addr.arpa", 0xaaab0f22e8b8, gravity): 0
[2020-08-17 20:15:15.338 6105/F5457] TCP worker forked for client 127.0.0.1 on interface lo (127.0.0.1)
[2020-08-17 20:15:15.339 6105/F5457] gravityDB_open(): Trying to open /etc/pihole/gravity.db in read-only mode
[2020-08-17 20:15:15.339 5457M] domain_in_list("4.1.0.10.in-addr.arpa", 0xaaab0f22c338, whitelist): 0
[2020-08-17 20:15:15.339 6105/F5457] gravityDB_open(): Setting location for temporary object to MEMORY
[2020-08-17 20:15:15.340 6105/F5457] gravityDB_open(): Preparing audit query

Add
Updated and flushed network table. No empty clients returned. Maybe it was a network hiccup.

DL6ER · August 18, 2020, 8:15pm

Yes, likely. However, there is a lot of hiccup catching and preventing code in FTL. From looking at your debug log, it was the client thinkpad-wifi which, apparently, didn't provide a MAC address at first, however, did so later. This is also is why this one entry has no address, 10.0.10.182 was already moved to the correctly identified device.

Relevant log lines

yubiuser:

[2020-08-17 20:15:15.274 5457/T5461] dbquery: "INSERT INTO network (hwaddr,interface,firstSeen,lastQuery,numQueries,macVendor) VALUES (?1,'N/A',?2,?3,?4,?5);" with arguments ?1-?5 = ("ip-10.0.10.182",1597688100,1597688082,8,"(null)")

yubiuser:

[2020-08-17 20:15:15.275 5457/T5461] dbquery: "UPDATE network_addresses SET name = ?1, nameUpdated = (cast(strftime('%s', 'now') as int)) WHERE ip = ?2" with arguments 1 = "thinkpad-wifi" and 2 = "10.0.10.182"

yubiuser · August 18, 2020, 8:38pm

A new one showed up

	N/A	N/A	unknown	2020-08-18 16:08:00	2020-08-18 14:37:53	2

How can the last query be before first seen?

Log

[2020-08-18 16:08:00.133 14127/T14131] Network table: 10.0.10.182 NOT known through ARP/neigh cache
[2020-08-18 16:08:00.134 14127/T14131] Network table: Adding new record for client with IP 10.0.10.182 and hwaddr ip-10.0.10.182
[2020-08-18 16:08:00.135 14127/T14131] Network table: 127.0.0.1 NOT known through ARP/neigh cache
[2020-08-18 16:08:00.135 14127/T14131] Network table: Client with IP 127.0.0.1 has recently be seen for network ID 7
[2020-08-18 16:08:00.137 14127/T14131] Network table: 10.0.10.190 NOT known through ARP/neigh cache
[2020-08-18 16:08:00.137 14127/T14131] Network table: Client with IP 10.0.10.190 has recently be seen for network ID 11
[2020-08-18 16:08:00.138 14127/T14131] Network table: Client 10.0.1.7 has zero new queries (count: 65, ARPcount: 0)
[2020-08-18 16:08:00.138 14127/T14131] Network table: 10.0.10.215 NOT known through ARP/neigh cache
[2020-08-18 16:08:00.139 14127/T14131] Network table: Client with IP 10.0.10.215 has recently be seen for network ID 8
[2020-08-18 16:08:00.140 14127/T14131] Network table: 10.0.10.64 NOT known through ARP/neigh cache
[2020-08-18 16:08:00.140 14127/T14131] Network table: Client with IP 10.0.10.64 has recently be seen for network ID 12
[2020-08-18 16:08:00.141 14127/T14131] Network table: Client 10.0.1.2 has zero new queries (count: 406, ARPcount: 0)
[2020-08-18 16:08:00.141 14127/T14131] Network table: 10.0.40.3 NOT known through ARP/neigh cache
[2020-08-18 16:08:00.142 14127/T14131] Network table: Adding new record for client with IP 10.0.40.3 and hwaddr ip-10.0.40.3
[2020-08-18 16:08:00.144 14127/T14131] Network table: Client 10.0.1.4 has zero new queries (count: 2, ARPcount: 0)
[2020-08-18 16:08:00.144 14127/T14131] Network table: Client 10.0.1.136 known through ARP/neigh cache
[2020-08-18 16:08:00.144 14127/T14131] Network table: 10.0.10.84 NOT known through ARP/neigh cache
[2020-08-18 16:08:00.145 14127/T14131] Network table: Client with IP 10.0.10.84 has recently be seen for network ID 9
[2020-08-18 16:08:00.146 14127/T14131] Network table: 10.0.10.136 NOT known through ARP/neigh cache
[2020-08-18 16:08:00.146 14127/T14131] Network table: Client with IP 10.0.10.136 has recently be seen for network ID 10

DL6ER · August 18, 2020, 9:02pm

"First seen" rather means: "Time this client was added to the network table (for the first time)".

When greping your log for 10.0.10.182 you will likely find a record after 16:08:00 which is like

Network table: Adding new record for client with IP 10.0.10.182 and hwaddr [some MAC address here]

This is the time when the address gets rerouted from the mock-device ip-10.0.10.182 to a newly created device with a correct record. I pushed another change which should clean up these useless leftover records.

yubiuser · August 18, 2020, 9:10pm

Found it a few hours later

[2020-08-18 20:49:00.105 14201/T14205] Network table: Adding new record for client with IP 10.0.10.182 and hwaddr 80

Add

.. and with the latest update the entry is gone.