Host name of client xxx => contains (at least) one invalid character at position 0

General Beta 6.0
28

agree, what could we do to capture this?

29

you already did

We need to find the lines starting in Mar 28 09:00:00 dnsmasq[56685] (or any other date/number) telling us details about the DHCP negotiation happening with this particular device. Best is to capture the log for a few days and then starts looking once the warning is triggered.

30

Please tell me what to do here...like which log will I look for/in?

FTL.log shows only:

2024-03-28 00:42:18.123 [56685/T62702] INFO: Optimized database in 0.060 seconds
2024-03-28 09:00:00.567 [56685/T62704] WARNING: Host name of client "192.168.2.144" => "\u0003" contains (at least) one invalid character (hex 03) at position 0
2024-03-28 10:12:28.843 [56685/T62711] WARNING: API: Unauthorized

I saw the below, not related, just wanted to share:

2024-03-28 13:36:35.023 [89037/T89050] ERROR: get_client_groupids("192.168.2.102", "68:ff:7b:c5:54:c7") - SQL error step: database is locked
2024-03-28 13:36:35.023 [89037/T89050] ERROR: get_client_groupids("192.168.2.102") - SQL error step: database is locked
2024-03-28 13:36:35.023 [89037/T89050] ERROR: get_client_groupids("192.168.2.132") - SQL error step: database is locked
2024-03-28 13:36:35.023 [89037/T89050] ERROR: get_client_groupids("192.168.2.132") - SQL error step: database is locked
2024-03-28 13:36:35.023 [89037/T89050] ERROR: get_client_groupids("192.168.2.181") - SQL error step: database is locked
2024-03-28 13:36:35.023 [89037/T89050] ERROR: get_client_groupids("192.168.2.181") - SQL error step: database is locked
2024-03-28 13:36:35.023 [89037/T89050] ERROR: get_client_groupids("192.168.2.180") - SQL error step: database is locked
2024-03-28 13:36:35.023 [89037/T89050] ERROR: get_client_groupids("192.168.2.180") - SQL error step: database is locked
31

It is /var/log/pihole/pihole.log that will have it. I cannot really predict what we are looking for - something DHCP related concerning these devices (you should be able to search for the IP address)

1 Like
32

Got the error again.

2024-04-02 03:00:00 HOSTNAME	Host name of client 192.168.2.246 => "\u0003" contains (at least) one invalid character (hex 03) at position 0

Again, the pihole.log don't give any idea.

Apr  2 03:00:00 dnsmasq[124255]: DHCP 192.168.2.100 is hs100-1.eth2
Apr  2 03:00:00 dnsmasq[124255]: query[PTR] 7.2.168.192.in-addr.arpa from 127.0.0.1
Apr  2 03:00:00 dnsmasq[124255]: DHCP 192.168.2.7 is meross-erik.eth2
Apr  2 03:00:00 dnsmasq[124255]: query[PTR] 4.2.168.192.in-addr.arpa from 127.0.0.1
Apr  2 03:00:00 dnsmasq[124255]: DHCP 192.168.2.4 is hanlop-u6-2.eth2
Apr  2 03:00:00 dnsmasq[124255]: query[PTR] 240.2.168.192.in-addr.arpa from 127.0.0.1
Apr  2 03:00:00 dnsmasq[124255]: config 192.168.2.240 is NXDOMAIN
Apr  2 03:00:00 dnsmasq[124255]: query[PTR] 246.2.168.192.in-addr.arpa from 127.0.0.1
**Apr  2 03:00:00 dnsmasq[124255]: DHCP 192.168.2.246 is <name unprintable>**
Apr  2 03:00:00 dnsmasq[124255]: forwarded 246.2.168.192.in-addr.arpa to 9.9.9.9
Apr  2 03:00:00 dnsmasq[124255]: dnssec-query[DS] in-addr.arpa to 9.9.9.9
Apr  2 03:00:00 dnsmasq[124255]: reply in-addr.arpa is DS for keytag 47054, algo 8, digest 2
Apr  2 03:00:00 dnsmasq[124255]: reply in-addr.arpa is DS for keytag 53696, algo 8, digest 2
Apr  2 03:00:00 dnsmasq[124255]: reply in-addr.arpa is DS for keytag 63982, algo 8, digest 2
Apr  2 03:00:00 dnsmasq[124255]: reply in-addr.arpa is DS for keytag 54956, algo 8, digest 2

Same for FTL.log no hint on what/why.

2024-04-02 03:00:00.824 [124255/T124270] WARNING: Host name of client "192.168.2.246" => "\u0003" contains (at least) one invalid character (hex 03) at position 0

Only thing I can add, is that .2.246 is for a new device for which I hadn't added the static address.
In the list over Active DHCP leases the device was shown as L630, in the static DHCP I have changed the IP and used lower case for the name.
To see if any difference.

33

Are there no dnsmasq-dhcp lines in /var/log/pihole/pihole.log? Maybe its .1 variant?

34

My bad didn't search for that and I forgot to save a copy of the pihole.log, I'll keep looking for the issue and get all info I can.
Need to figure out how to get the copy of the log file moved out from the Pi, I tried different ways before, but keep getting Not Authorised.

35

Then chances are that the device's DHCP client has presented an invalid hostname during DHCP negotiation.

Would you be able to check the hostname on the device itself, or perhaps even edit it?

Also, you could check the logs for DHCP negotiations (though to be honest, I don't recall whether the logs actually would have the hostname as presented by a client):

grep -n "dhcp" /var/log/pihole/pihole.log

If you know your 192.168.2.246's (current?) MAC address, you could also grep for that.

36

Hi,
I got copies of the pihole.log extracted.
I don't think the device presented an invalid host name, because:

This is the first time the device came online.

Apr  1 14:43:52 dnsmasq-dhcp[92440]: 135197707 client provides name: L630
Apr  1 14:43:52 dnsmasq-dhcp[92440]: 135197707 DHCPREQUEST(eth0) 192.168.2.246 f0:a7:31:d1:fc:d4 
Apr  1 14:43:52 dnsmasq-dhcp[92440]: 135197707 tags: eth0
Apr  1 14:43:52 dnsmasq-dhcp[92440]: 135197707 DHCPACK(eth0) 192.168.2.246 f0:a7:31:d1:fc:d4 L630

Then rest of 1st April and into 2nd April all ok up to 02:00:00

Apr  1 15:00:00 dnsmasq[92440]: query[PTR] 246.2.168.192.in-addr.arpa from 127.0.0.1
Apr  1 15:00:00 dnsmasq[92440]: DHCP 192.168.2.246 is L630.eth2
Apr  1 22:00:00 dnsmasq[124255]: query[PTR] 246.2.168.192.in-addr.arpa from 127.0.0.1
Apr  1 22:00:00 dnsmasq[124255]: DHCP 192.168.2.246 is L630.eth2
Apr  1 23:00:00 dnsmasq[124255]: query[PTR] 246.2.168.192.in-addr.arpa from 127.0.0.1
Apr  1 23:00:00 dnsmasq[124255]: DHCP 192.168.2.246 is L630.eth2
Apr  2 00:00:00 dnsmasq[124255]: query[PTR] 246.2.168.192.in-addr.arpa from 127.0.0.1
Apr  2 00:00:00 dnsmasq[124255]: DHCP 192.168.2.246 is L630.eth2
Apr  2 01:00:00 dnsmasq[124255]: query[PTR] 246.2.168.192.in-addr.arpa from 127.0.0.1
Apr  2 01:00:00 dnsmasq[124255]: DHCP 192.168.2.246 is L630.eth2
Apr  2 02:00:00 dnsmasq[124255]: query[PTR] 246.2.168.192.in-addr.arpa from 127.0.0.1
Apr  2 02:00:00 dnsmasq[124255]: DHCP 192.168.2.246 is L630.eth2

At 3am the error happens

Apr  2 03:00:00 dnsmasq[124255]: query[PTR] 246.2.168.192.in-addr.arpa from 127.0.0.1
Apr  2 03:00:00 dnsmasq[124255]: DHCP 192.168.2.246 is <name unprintable>
Apr  2 03:00:00 dnsmasq[124255]: forwarded 246.2.168.192.in-addr.arpa to 9.9.9.9
Apr  2 03:00:00 dnsmasq[124255]: dnssec-query[DS] in-addr.arpa to 9.9.9.9
Apr  2 03:00:00 dnsmasq[124255]: reply in-addr.arpa is DS for keytag 47054, algo 8, digest 2
Apr  2 03:00:00 dnsmasq[124255]: reply in-addr.arpa is DS for keytag 53696, algo 8, digest 2
Apr  2 03:00:00 dnsmasq[124255]: reply in-addr.arpa is DS for keytag 63982, algo 8, digest 2
Apr  2 03:00:00 dnsmasq[124255]: reply in-addr.arpa is DS for keytag 54956, algo 8, digest 2
Apr  2 03:00:00 dnsmasq[124255]: dnssec-query[DS] 192.in-addr.arpa to 9.9.9.9
Apr  2 03:00:00 dnsmasq[124255]: dnssec-query[DNSKEY] in-addr.arpa to 9.9.9.9
Apr  2 03:00:00 dnsmasq[124255]: reply in-addr.arpa is truncated[DNSKEY]
Apr  2 03:00:00 dnsmasq[124255]: validation result is TRUNCATED
Apr  2 03:00:00 dnsmasq[124255]: reply is truncated
Apr  2 03:00:00 dnsmasq[124255]: validation result is INSECURE

At the next requests the answer is NXDOMAIN

Apr  2 04:00:00 dnsmasq[124255]: query[PTR] 246.2.168.192.in-addr.arpa from 127.0.0.1
Apr  2 04:00:00 dnsmasq[124255]: config 192.168.2.246 is NXDOMAIN
Apr  2 05:00:00 dnsmasq[124255]: query[PTR] 246.2.168.192.in-addr.arpa from 127.0.0.1
Apr  2 05:00:00 dnsmasq[124255]: config 192.168.2.246 is NXDOMAIN
Apr  2 06:00:00 dnsmasq[124255]: query[PTR] 246.2.168.192.in-addr.arpa from 127.0.0.1
Apr  2 06:00:00 dnsmasq[124255]: config 192.168.2.246 is NXDOMAIN

At 7am the answer is same as at 2am, and continues with same response ...is L630.eth2

Apr  2 07:00:00 dnsmasq[124255]: query[PTR] 246.2.168.192.in-addr.arpa from 127.0.0.1
Apr  2 07:00:00 dnsmasq[124255]: DHCP 192.168.2.246 is L630.eth2

At 2pm on the 2nd I changed the dynamic IP addressing to be a static IP address and changed the name from L630 to l630.

Apr  2 14:00:00 dnsmasq[141587]: query[PTR] 145.2.168.192.in-addr.arpa from 127.0.0.1
Apr  2 14:00:00 dnsmasq[141587]: DHCP 192.168.2.145 is l630-1.eth2

Attached the two log files as zips.

pihole.log 1st and 2nd April seh2000.zip (4.1 MB)

37

Hi
Again the error popped up.
No real indicator of why, only thing in common between last one on April 1 and this one on April 7 is it happens at a the whole hour - Last at 15:00:00 / This 19:00:00 which appears to be the time when the DHCP lease time is renewed. My lease time is set to 6 hours.

Pi-hole diagnostic:

2024-04-07 19:00:00	HOSTNAME	Host name of client 192.168.2.144 => "\u0003" contains (at least) one invalid character (hex 03) at position 0

Tail log files:
pihole.log = issue overwritten

FTL.log only one entry:

2024-04-07 19:00:00.145 WARNING Host name of client "192.168.2.144" => "\u0003" contains (at least) one invalid character (hex 03) at position 0

/var/log/pihole/FTL.log

2024-04-07 04:49:32.179 INFO Compiled 26 allow and 2 deny regex for 52 clients in 125.9 msec
2024-04-07 19:00:00.145 WARNING Host name of client "192.168.2.144" => "\u0003" contains (at least) one invalid character (hex 03) at position 0

pihole.log.1

Apr  7 19:00:00 dnsmasq[141587]: query[PTR] 122.2.168.192.in-addr.arpa from 127.0.0.1
Apr  7 19:00:00 dnsmasq[141587]: DHCP 192.168.2.122 is kp105-3.eth2
Apr  7 19:00:00 dnsmasq[141587]: query[PTR] 144.2.168.192.in-addr.arpa from 127.0.0.1
Apr  7 19:00:00 dnsmasq[141587]: DHCP 192.168.2.144 is <name unprintable>
Apr  7 19:00:00 dnsmasq[141587]: forwarded 144.2.168.192.in-addr.arpa to 9.9.9.9
Apr  7 19:00:00 dnsmasq[141587]: dnssec-query[DS] 192.in-addr.arpa to 9.9.9.9
Apr  7 19:00:00 dnsmasq[141587]: dnssec-query[DNSKEY] in-addr.arpa to 9.9.9.9
Apr  7 19:00:00 dnsmasq[141587]: reply in-addr.arpa is truncated[DNSKEY]
Apr  7 19:00:00 dnsmasq[141587]: validation result is TRUNCATED
Apr  7 19:00:00 dnsmasq[141587]: reply is truncated

FTL.log.1

2024-04-07 04:49:32.049 [141587/T144838] INFO: Gravity database has been updated, reloading now
2024-04-07 04:49:32.179 [141587/T144838] INFO: Compiled 26 allow and 2 deny regex for 52 clients in 125.9 msec
2024-04-07 19:00:00.145 [141587/T144840] WARNING: Host name of client "192.168.2.144" => "\u0003" contains (at least) one invalid character (hex 03) at position 0
38

Most likely, this is just a symptomatical observation, rather than a cause:
Pi-hole regulary does a reverse loookup (PTR) for client IPs at the sharp hour, and that's just the time when the irregular hostname is detected.

Setting a DHCP lease reservation for that client device NIC would preclude that the offending name would presented by that client during DHCP lease negotiation.

As a result, I would expect the hostname warning to not reappear again.

Your most recent observation is for a different IP, .144 instead of .145.
Do those IPs belong to the same client device network interface?

39

Yes, there are like 22 devices from same vendor (TP-Link) on same interface. To date I have only seen it from these two devices .144 / .145
I'll do a test where I remove the power from each to see the behaviour.

40

It's rather unlikely that 22 devices would share the same NIC.

A client device (e.g. a laptop) may have several network interfaces (e.g. eth0 and wlan0), and commonly each NIC would carry a separate IP.

My question aims to find out whether your .144 and .145 belong to the very same NIC, e.g. your laptop's eth0.

41

Yes, you are right my bad in expressing my self.
I said eth0 as I was thinking on the Pi-hole.
ISP > Router >
eth1 > switch02 > LAN
Port 1 = Pi-hole1 (DHCP from Router)
Port 2 ~ 15 (wired computers/laptops/game boxes via CAT6)
eth2 > switch01 > WLAN
Port 1 = Pi-hole2 (DHCP) {static IP range 2.2 to 2.239 / dynamic IP range 2.240 to 2.249
Port 2 = Wi-Fi AP1 2.4Mhz {22 devices here same vendor = all smart devices, other devices from other vendors)
Port 3 = Wi-Fi AP2 5.0Mhz {mobiles and tables
Port 4 = PoE switch 8 Port {security IP cameras
Port 5 = Raspberry Pi (not Pi-hole)
Port 6 = Sky Box
Port 8 = Sky Box

42

This more and more seems to point into the direction of a bug in dnsmasq's cache - which is where pihole-FTL gets the names from. Unfortunately, this will be very hard to debug and I'm not even sure where to start. At this point I'm tempted to exclude this would be a Pi-hole issue as we are never messing with the DNS cache and

comes straight from the dnsmasq core. It is very possible that other PTR queries are affected just as well, however, PTRs are not done very often and your Pi-hole is only doing automatic PTR lookups for devices in your local network - which makes it likely to get noticed here first (or, at all).

What would maybe be interesting is the content of /etc/pihole/dhcp.leaes when this happens, however, as we are not seeing issues during negotiation

(emphasis on L630 at the end of the line), I would actually not really expect erroneous content to be found herein...

Does

zgrep "192.168.2.144" /var/log/pihole/*

reveal anything interesting we have not already seen above?

43

Had a look in dhcp.leases strangely enough neither 2.144 and 2.145 appears there, not sure why.

Had then a look in pihole.log and sometimes they appears with their "name" (l630-1 and l630-2 and other times with "NXDOMAIN", however that didn't result in any error.

Apr  8 19:00:00 dnsmasq[141587]: query[PTR] 21.2.168.192.in-addr.arpa from 127.0.0.1
Apr  8 19:00:00 dnsmasq[141587]: DHCP 192.168.2.21 is sky-q-bedroom.eth2
Apr  8 19:00:00 dnsmasq[141587]: query[PTR] 144.2.168.192.in-addr.arpa from 127.0.0.1
Apr  8 19:00:00 dnsmasq[141587]: **config 192.168.2.144 is NXDOMAIN**
Apr  8 19:00:00 dnsmasq[141587]: query[PTR] 152.2.168.192.in-addr.arpa from 127.0.0.1
Apr  8 19:00:00 dnsmasq[141587]: DHCP 192.168.2.152 is kl130-3.eth2
Apr  8 19:00:00 dnsmasq[141587]: query[PTR] 5.2.168.192.in-addr.arpa from 127.0.0.1
Apr  8 19:00:00 dnsmasq[141587]: DHCP 192.168.2.5 is obi200.eth2
Apr  8 19:00:00 dnsmasq[141587]: query[PTR] 145.2.168.192.in-addr.arpa from 127.0.0.1
Apr  8 19:00:00 dnsmasq[141587]: **config 192.168.2.145 is NXDOMAIN**
Apr  8 19:00:00 dnsmasq[141587]: query[PTR] 130.2.168.192.in-addr.arpa from 127.0.0.1
Apr  8 19:00:00 dnsmasq[141587]: DHCP 192.168.2.130 is p100-1.eth2

The output from

zgrep "192.168.2.144" /var/log/pihole/*

is very long for both 2.144 and 2.145 therefore attached as two text files, not sure if content helps.

seh 144 8April2024.txt (56.6 KB)
seh 145 8April2024.txt (50.7 KB)

46

@DL6ER
Happened again, but for another device same vendor but different type / model.

sudo zgrep "192.168.2.141" /var/log/pihole/*
#/var/log/pihole/FTL.log:2024-04-12 03:00:00.418 [773/T1205] WARNING: Host name of client "192.168.2.141" => "\u0003" contains (at least) one invalid character (hex 03) at position 0
/var/log/pihole/pihole_debug.log:       "14:EB:B6:D2:9E:5D,192.168.2.141,l530-2",
/var/log/pihole/pihole.log:Apr 12 00:17:07 dnsmasq[773]: query[A] pool.ntp.org from 192.168.2.141
/var/log/pihole/pihole.log:Apr 12 00:47:04 dnsmasq[773]: query[A] pool.ntp.org from 192.168.2.141
/var/log/pihole/pihole.log:Apr 12 01:00:00 dnsmasq[773]: DHCP 192.168.2.141 is l530-2.eth2
/var/log/pihole/pihole.log:Apr 12 01:17:02 dnsmasq[773]: query[A] pool.ntp.org from 192.168.2.141
/var/log/pihole/pihole.log:Apr 12 01:46:57 dnsmasq[773]: query[A] pool.ntp.org from 192.168.2.141
/var/log/pihole/pihole.log:Apr 12 02:00:00 dnsmasq[773]: DHCP 192.168.2.141 is l530-2.eth2
/var/log/pihole/pihole.log:Apr 12 02:16:57 dnsmasq[773]: query[A] pool.ntp.org from 192.168.2.141
/var/log/pihole/pihole.log:Apr 12 02:46:57 dnsmasq[773]: query[A] pool.ntp.org from 192.168.2.141
/var/log/pihole/pihole.log:Apr 12 03:00:00 dnsmasq[773]: DHCP 192.168.2.141 is <name unprintable>
/var/log/pihole/pihole.log:Apr 12 03:16:17 dnsmasq-dhcp[773]: 561441124 DHCPREQUEST(eth0) 192.168.2.141 14:eb:b6:d2:9e:5d
/var/log/pihole/pihole.log:Apr 12 03:16:17 dnsmasq-dhcp[773]: 561441124 DHCPACK(eth0) 192.168.2.141 14:eb:b6:d2:9e:5d l530-2
/var/log/pihole/pihole.log:Apr 12 03:16:57 dnsmasq[773]: query[A] pool.ntp.org from 192.168.2.141
/var/log/pihole/pihole.log:Apr 12 03:18:27 dnsmasq[773]: query[A] pool.ntp.org from 192.168.2.141
/var/log/pihole/pihole.log:Apr 12 03:47:07 dnsmasq[773]: query[A] pool.ntp.org from 192.168.2.141
/var/log/pihole/pihole.log:Apr 12 04:00:00 dnsmasq[773]: DHCP 192.168.2.141 is l530-2.eth2

Not sure what to do or if just ignore?

48

I do neither really know what could be the cause - else than a big bug hiding somewhere in a really good way. What might be worth trying to limit the places where we have to look would be disabling the cache optimizer like
grafik

49

Disabled!
It is strange, I had the "hope" that it was related to the two 2.144 and .2.145 as they are new devices to the network. But with the last issue on 2.141 that "hope" don't hold ( I think), because I have two devices of same type/model, with both being in the network for many months.

51

The error has not occurred anymore.
I will also turn off the cache.