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

General Beta 6.0
53

Hmm, no further feedback from you but I have further feedback. After some more inspection of the code I seem to have many possible causes for this odd behavior but I may still have found what is going wrong - I just don't know know yet how to get to this point...

If you are still experiencing this (or can reproduce it) and are also still willing to help, I'd like to ask you to run

pihole checkout ftl fix/dhcp_names

and check out for the error to happen again. Even without any debug options being enabled, this version of FTL should be much more verbose in logging to /var/log/pihole/FTL.log.

My hope is that we see that something odd is happening to the leases before they start behaving oddly to have something we can continue to work on. Together, we'll finally get down to it!

54

I have enabled the fix.

I had the error yesterday...But as I had created a new install from scratch I had forgotten to disable the cache optimizer, I did the disabling after I had the error yesterday.

admin@Pi4-2:~ $ sudo zgrep "192.168.2.145" /var/log/pihole/*
/var/log/pihole/FTL.log.1:2024-04-29 05:00:00.765 [58503/T58562] WARNING: Host name of client "192.168.2.145" => "\u0007" contains (at least) one invalid character (hex 07) at position 0
/var/log/pihole/FTL.log.2.gz:2024-04-28 08:00:00.498 [849/T5407] WARNING: Host name of client "192.168.2.145" => "\n" contains (at least) one invalid character (hex 0a) at position 0
/var/log/pihole/FTL.log.2.gz:2024-04-28 13:32:03.394 [58503/T58560] ERROR: get_client_groupids("192.168.2.145", "eth0") - SQL error step: database is locked
/var/log/pihole/FTL.log.2.gz:2024-04-28 13:32:03.394 [58503/T58560] ERROR: get_client_groupids("192.168.2.145") - SQL error step: database is locked
/var/log/pihole/FTL.log.3.gz:2024-04-26 21:00:00.103 [849/T5407] WARNING: Host name of client "192.168.2.145" => "\u0007" contains (at least) one invalid character (hex 07) at position 0
/var/log/pihole/pihole.log:Apr 30 00:06:35 dnsmasq[58503]: query[A] pool.ntp.org from 192.168.2.145
55

Yeah, in the end we need to find the real cause, it may be the cache optimizer - as this is the most recent most severe change to the cache - but it doesn't have to be necessarily.

56

I'll run a few days with disabled and if nothing the enabling again.

1 Like
57

Still no more errors.
I applied the fix and will see...

58

I had the same issue with a Meross Smart Switch, which shows up the device name as „Meross Smart Switch“ with spaces. On the router it has „-„ between the three words.

I will try to use the patch too and see what happened.

59

Just a small hint: Don't be mistaken by the branch name starting in fix/... - we do not expect any difference besides some extra logging in FTL.log which will hopefully point us to the location where we will need to work on a fix!

1 Like
60

@DL6ER

Hello,
So far no error, but I now see with the FTL fix a constant stream of messages similar to the below
and attached snip sometimes just with minutes between a series of messages, sometimes with half an hour between or a couple of hours between.
Not sure if OK or not ok?

Didn't copy out whole log.
SH Snip FTL_Log 02May2024.txt (13.7 KB)

Sample...

2024-05-02 10:30:10.205 [84221M] INFO: Adding DHCP->DNS entry for l530-2.wi-fi >
2024-05-02 10:30:10.205 [84221M] INFO: Adding DHCP->DNS entry for l530-2 at 192>
2024-05-02 10:37:37.800 [84221M] INFO: Adding DHCP->DNS entry for esp_44b71d.wi>
2024-05-02 10:37:37.801 [84221M] INFO: Adding DHCP->DNS entry for esp_44b71d at>
2024-05-02 10:37:37.801 [84221M] INFO: Adding DHCP->DNS entry for hanlop-u6-02.>
2024-05-02 10:37:37.801 [84221M] INFO: Adding DHCP->DNS entry for hanlop-u6-02 >
2024-05-02 10:37:37.801 [84221M] INFO: Adding DHCP->DNS entry for hs110-1.wi-fi>
2024-05-02 10:37:37.802 [84221M] INFO: Adding DHCP->DNS entry for hs110-1 at 19>
63

Everything seems fine in you log file. We'll only see what is going on once the issue becomes visible through the hostname error.

64

Thanks - will continue to monitor...

65

@DL6ER
Just had one incident, came after I had changed DNS Optimizer back from -1 to 3600 on 3 of May.
Steen

Pi-hole Tail FTL.log:

2024-05-05 18:57:30.897 INFO DHCP lease 192.168.2.141 expired (Sun May 5 18:57:30 2024 )

2024-05-05 18:57:30.905 INFO kill_name(): Freeing old hostname lease 192.168.2.141 -> (null)

2024-05-05 18:57:30.905 INFO kill_name(): Freeing hostname lease 192.168.2.141 -> l530-2

2024-05-05 18:57:30.906 INFO do_script_run(): Freeing lease 192.168.2.141 -> l530-2.wi-fi

2024-05-05 19:00:00.438 WARNING Host name of client "192.168.2.141" => "\u000b" contains (at least) one invalid character (hex 0b) at position 0

2024-05-05 19:04:39.263 INFO Adding DHCP->DNS entry for tv-living.wi-fi at 192.168.2.23

Pi-hole diagnosis:

2024-05-05 19:00:00 HOSTNAME Host name of client `192.168.2.141` => `"\u000b"` contains (at least) one invalid character (hex 0b) at position 0

/var/log/pihole/pihole.log:

May  5 19:00:00 dnsmasq[4395]: DHCP 192.168.2.145 is l630-2.wi-fi
May  5 19:00:00 dnsmasq[4395]: query[PTR] 141.2.168.192.in-addr.arpa from 127.0.0.1
May  5 19:00:00 dnsmasq[4395]: DHCP 192.168.2.141 is **<name unprintable>**
May  5 19:00:00 dnsmasq[4395]: forwarded 141.2.168.192.in-addr.arpa to 1.0.0.1

/var/log/pihole/FTL.log

2024-05-05 18:57:30.897 [4395M] INFO: DHCP lease 192.168.2.141 expired (Sun May  5 18:57:30 2024
)
2024-05-05 18:57:30.905 [4395M] INFO: kill_name(): Freeing old hostname lease 192.168.2.141 -> (null)
2024-05-05 18:57:30.905 [4395M] INFO: kill_name(): Freeing hostname lease 192.168.2.141 -> l530-2
2024-05-05 18:57:30.906 [4395M] INFO: do_script_run(): Freeing lease 192.168.2.141 -> l530-2.wi-fi
2024-05-05 19:00:00.438 [4395/T4413] WARNING: Host name of client "192.168.2.141" => "\u000b" contains (at least) one invalid character (hex 0b) at position 0
2024-05-05 19:04:39.263 [4395M] INFO: Adding DHCP->DNS entry for tv-living.wi-fi at 192.168.2.23

Your debug token is:

https://tricorder.pi-hole.net/8elPjkEz/

Think nothing new...

1 Like
66

Thanks, this is spot-in what we needed. It confirms that the hostname memory is being released once the lease expires. This happens only moments before the hostnames are updated where the cache optimizer is indeed the problem - it accesses released memory returning garbage data, possibly even crashing the entire service.

I am in contact with Simon Kelley, the maintainer of the dnsmasq server which is embedded in FTL to negotiate what would be the best way of fixing this. We try to avoid conflicting code changes to ensure we can easily incorporate future updates and meanwhile fix bugs for original dnsmasq users as well.

I will come back to you with a real fix once we hear back from Simon Kelley.

2 Likes
67

Glad I could assist a bit...
Just wonder why it is not for all devices, just for the same few?
Anything I am to do - let me know!
Thanks again!

68

So far, the required step for this to happen is that the lease will have to be expired just before names are updated. It may be a bug in said devices that they continue running with expired leases and don't bother renewing? Or can it be that they've been switched off when the error is triggered?

69

@DL6ER
Good Day,
I got another one, just for data collection I am sharing.
Please let me know if I should share upcoming events with you.
Steen

Pi-hole diagnosis:

2024-05-07 01:00:00	HOSTNAME	Host name of client 192.168.2.145 => "\n" contains (at least) one invalid character (hex 0a) at position 0

From //var/log/pihole/FTL.log:

2024-05-07 00:55:42.839 [4395M] INFO: Adding DHCP->DNS entry for Echo-S20-FE.wi-fi at 192.168.2.245
2024-05-07 00:55:42.840 [4395M] INFO: Adding DHCP->DNS entry for Echo-S20-FE at 192.168.2.245
2024-05-07 00:58:48.823 [4395M] INFO: DHCP lease 192.168.2.145 expired (Tue May  7 00:58:48 2024
)
2024-05-07 00:58:48.830 [4395M] INFO: kill_name(): Freeing old hostname lease 192.168.2.145 -> (null)
2024-05-07 00:58:48.830 [4395M] INFO: kill_name(): Freeing hostname lease 192.168.2.145 -> l630-2
2024-05-07 00:58:48.831 [4395M] INFO: do_script_run(): Freeing lease 192.168.2.145 -> l630-2.wi-fi
2024-05-07 01:00:00.140 [4395/T4413] WARNING: Host name of client "192.168.2.145" => "\n" contains (at least) one invalid character (hex 0a) at position 0
2024-05-07 01:08:16.366 [4395M] INFO: Adding DHCP->DNS entry for l530-2.wi-fi at 192.168.2.141
2024-05-07 01:08:16.366 [4395M] INFO: Adding DHCP->DNS entry for l530-2 at 192.168.2.141

From /var/log/pihole/pihole.log:

May  7 01:00:00 dnsmasq[4395]: query[PTR] 153.2.168.192.in-addr.arpa from 127.0.0.1
May  7 01:00:00 dnsmasq[4395]: DHCP 192.168.2.153 is kl130-4.wi-fi
May  7 01:00:00 dnsmasq[4395]: query[PTR] 145.2.168.192.in-addr.arpa from 127.0.0.1
May  7 01:00:00 dnsmasq[4395]: DHCP 192.168.2.145 is <name unprintable>
May  7 01:00:00 dnsmasq[4395]: forwarded 145.2.168.192.in-addr.arpa to 1.1.1.1
May  7 01:00:00 dnsmasq[4395]: dnssec-query[DS] 168.192.in-addr.arpa to 1.1.1.1
May  7 01:00:00 dnsmasq[4395]: validation 145.2.168.192.in-addr.arpa is BOGUS

At next the same IP-device OK.

May  7 01:26:53 dnsmasq[4395]: reply api.amazon.com is 209.54.177.153
May  7 01:26:53 dnsmasq-dhcp[4395]: DHCPREQUEST(eth0) 192.168.2.145 f0:a7:31:d1:fc:24
May  7 01:26:53 dnsmasq-dhcp[4395]: DHCPACK(eth0) 192.168.2.145 f0:a7:31:d1:fc:24 l630-2
70

I don't think we need any further but one question remains open why it's always the same devices:

71

That's what I wonder too...
From what I gather then it is there 3 devices:
2.141, 2.144 & 2.145
All are what one can call smart devices = light bulbs, the two last are same type/model. All 3 from same vendor (TP-Link), which I have some 10-15 other devices from a mixture of bulbs and switches.
All 3 are "on" all the time, to be understood that they communicate with an App via Wi-Fi, the light comes on daily at specific times (all 3 at the same time). So the radio part of the 3 is on all the time.
I just checked on the UniFi Controller which shows connectivity to the 3 devices are excellent with an OK ap/client signal balance.
First 2 are located at same location (front of the house) while the last of the 3 is located behind the house.
For the 2 first there is another device 2meter away which never showed any issue, and for the last there is a new device located 1.5 meter away, which also never showed any issue.
I could - perhaps - try 3 other IPs either with same name or leave the name as the device have?

72

Hmm, than its much more likely that there is ...

which is ... something we cannot fix but we can certainly fix the underlying issue causing the names to not resolve (or rather: resolve to crap).

73

...understand, but they do renew...
I can change the DHCP renewal time, right now its each 6 hour to see if issue could be happening more often (should renewal time be less or longer)?

74

How do you know? From the log excerpts above, they seem to not renew causing the lease to expire at some point.

Do you still have the config option dhcp.logging set to true ?

image
image720×316 35.9 KB

I'm asking because - in one log snippet above - we have seen the underlying DHCP activity but not in the more recent ones:

Could you grep your logs specifically for dnsmasq-dhcp + some IP address where you notice the error next time?