Stubby crashes when pihole cleanup is run via cron?

pi_user · January 13, 2022, 10:48am

Using :

Pi-hole version is v5.8.1 (Latest: v5.8.1)
AdminLTE version is v5.10.1 (Latest: v5.10.1)
FTL version is v5.13 (Latest: v5.13)

and

Stubby 0.2.5 (upstream NextDNS)

Issue

Pihole dashboard says SERVFAIL for DNS queries
Internet is cut off (naturally due to DNS not resolving)
Stubby logs show this weird error :

Jan 13 15:41:27 raspberrypi stubby[19413]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict.

Frequency : once every 2 days.

Fix : Restarting stubby daemon helps and DNS starts resolving.

Syslog in R-Pi :

Jan 13 14:39:24 raspberrypi systemd[1]: Starting Clean php session files...
Jan 13 14:39:25 raspberrypi systemd[1]: phpsessionclean.service: Succeeded.
Jan 13 14:39:25 raspberrypi systemd[1]: Started Clean php session files.
Jan 13 14:40:01 raspberrypi CRON[8740]: (root) CMD (   PATH="$PATH:/usr/sbin:/usr/local/bin/" pihole updatechecker local)
Jan 13 14:50:01 raspberrypi CRON[8813]: (root) CMD (   PATH="$PATH:/usr/sbin:/usr/local/bin/" pihole updatechecker local)
Jan 13 14:53:01 raspberrypi CRON[8851]: (root) CMD (   PATH="$PATH:/usr/sbin:/usr/local/bin/" pihole updatechecker remote)
Jan 13 14:56:11 raspberrypi stubby[19413]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict.
Jan 13 14:56:11 raspberrypi stubby[19413]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict.
Jan 13 14:56:11 raspberrypi stubby[19413]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict.
Jan 13 14:56:11 raspberrypi stubby[19413]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict.
Jan 13 15:00:01 raspberrypi CRON[8918]: (root) CMD (   PATH="$PATH:/usr/sbin:/usr/local/bin/" pihole updatechecker local)
Jan 13 15:09:01 raspberrypi CRON[8987]: (root) CMD (  [ -x /usr/lib/php/sessionclean ] && if [ ! -d /run/systemd/system ]; then /usr/lib/php/sessionclean; fi)
Jan 13 15:09:24 raspberrypi systemd[1]: Starting Clean php session files...
Jan 13 15:09:25 raspberrypi systemd[1]: phpsessionclean.service: Succeeded.
Jan 13 15:09:25 raspberrypi systemd[1]: Started Clean php session files.
Jan 13 15:10:01 raspberrypi CRON[9045]: (root) CMD (   PATH="$PATH:/usr/sbin:/usr/local/bin/" pihole updatechecker local)
Jan 13 15:17:01 raspberrypi CRON[9105]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Jan 13 15:20:01 raspberrypi CRON[9132]: (root) CMD (   PATH="$PATH:/usr/sbin:/usr/local/bin/" pihole updatechecker local)
Jan 13 15:30:01 raspberrypi CRON[9209]: (root) CMD (   PATH="$PATH:/usr/sbin:/usr/local/bin/" pihole updatechecker local)
Jan 13 15:35:09 raspberrypi rngd[404]: stats: bits received from HRNG source: 7880064
Jan 13 15:35:09 raspberrypi rngd[404]: stats: bits sent to kernel pool: 7827168
Jan 13 15:35:09 raspberrypi rngd[404]: stats: entropy added to kernel pool: 7827168
Jan 13 15:35:09 raspberrypi rngd[404]: stats: FIPS 140-2 successes: 394
Jan 13 15:35:09 raspberrypi rngd[404]: stats: FIPS 140-2 failures: 0
Jan 13 15:35:09 raspberrypi rngd[404]: stats: FIPS 140-2(2001-10-10) Monobit: 0
Jan 13 15:35:09 raspberrypi rngd[404]: stats: FIPS 140-2(2001-10-10) Poker: 0
Jan 13 15:35:09 raspberrypi rngd[404]: stats: FIPS 140-2(2001-10-10) Runs: 0
Jan 13 15:35:09 raspberrypi rngd[404]: stats: FIPS 140-2(2001-10-10) Long run: 0
Jan 13 15:35:09 raspberrypi rngd[404]: stats: FIPS 140-2(2001-10-10) Continuous run: 0
Jan 13 15:35:09 raspberrypi rngd[404]: stats: HRNG source speed: (min=338.967; avg=512.547; max=535.954)Kibits/s
Jan 13 15:35:09 raspberrypi rngd[404]: stats: FIPS tests speed: (min=10.993; avg=12.881; max=31.371)Mibits/s
Jan 13 15:35:09 raspberrypi rngd[404]: stats: Lowest ready-buffers level: 2
Jan 13 15:35:09 raspberrypi rngd[404]: stats: Entropy starvations: 0
Jan 13 15:35:09 raspberrypi rngd[404]: stats: Time spent starving for entropy: (min=0; avg=0.000; max=0)us
Jan 13 15:39:01 raspberrypi CRON[9279]: (root) CMD (  [ -x /usr/lib/php/sessionclean ] && if [ ! -d /run/systemd/system ]; then /usr/lib/php/sessionclean; fi)
Jan 13 15:39:24 raspberrypi systemd[1]: Starting Clean php session files...
Jan 13 15:39:25 raspberrypi systemd[1]: phpsessionclean.service: Succeeded.
Jan 13 15:39:25 raspberrypi systemd[1]: Started Clean php session files.
Jan 13 15:40:01 raspberrypi CRON[9335]: (root) CMD (   PATH="$PATH:/usr/sbin:/usr/local/bin/" pihole updatechecker local)
Jan 13 15:41:27 raspberrypi stubby[19413]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict.
Jan 13 15:41:27 raspberrypi stubby[19413]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict.
Jan 13 15:41:27 raspberrypi stubby[19413]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict.
Jan 13 15:41:27 raspberrypi stubby[19413]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict.
Jan 13 15:43:36 raspberrypi stubby[19413]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict.
Jan 13 15:43:36 raspberrypi stubby[19413]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict.
Jan 13 15:43:36 raspberrypi stubby[19413]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict.
Jan 13 15:43:36 raspberrypi stubby[19413]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict.
Jan 13 15:45:43 raspberrypi stubby[19413]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict.
Jan 13 15:45:43 raspberrypi stubby[19413]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict.
Jan 13 15:45:43 raspberrypi stubby[19413]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict.
Jan 13 15:45:43 raspberrypi stubby[19413]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict.
Jan 13 15:49:03 raspberrypi systemd[1]: Started Session c86 of user pi.

I tried running the same update commands mentioned in logs above and Stubby is not impacted.

Documentation for this error is present here | Under section GETDNS_RETURN_NO_SUCH_DICT_NAME

Is it caused by Pihole update cron or could be due to upstream provider?

gjerem · January 14, 2022, 6:14pm

I don’t know. Maybe you can check the status of stubby when the internet is down.

systemctl status stubby

You can add Restart=on-failure as here , if not present in /lib/systemd/system/stubby.service.

systemctl stop stubby
nano /lib/systemd/system/stubby.service
systemctl daemon-reload
systemctl start stubby

pi_user · January 14, 2022, 6:47pm

Thank you for the suggestion, I am going to try it and update in case it changes things for me.

Also, when the internet goes down, the stubby service show running but in the syslog and also in systemctl status check logs at the bottom I get the exact same string I mentioned in my post :

Jan 13 15:43:36 raspberrypi stubby[19413]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict.

At that time, all DNS queries show SERVFAIL in pihole panel.

jfb · January 15, 2022, 1:28am

I'm not following you here. What cleanup or update cron are you referring to?

pi_user · January 15, 2022, 12:35pm

I pasted the logs in the question, here are the lines :

Jan 13 14:40:01 raspberrypi CRON[8740]: (root) CMD (   PATH="$PATH:/usr/sbin:/usr/local/bin/" pihole updatechecker local)
Jan 13 14:50:01 raspberrypi CRON[8813]: (root) CMD (   PATH="$PATH:/usr/sbin:/usr/local/bin/" pihole updatechecker local)
Jan 13 14:53:01 raspberrypi CRON[8851]: (root) CMD (   PATH="$PATH:/usr/sbin:/usr/local/bin/" pihole updatechecker remote)
Jan 13 14:56:11 raspberrypi stubby[19413]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict.
Jan 13 14:56:11 raspberrypi stubby[19413]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict.

And this :

Jan 13 15:39:24 raspberrypi systemd[1]: Starting Clean php session files...
Jan 13 15:39:25 raspberrypi systemd[1]: phpsessionclean.service: Succeeded.
Jan 13 15:39:25 raspberrypi systemd[1]: Started Clean php session files.
Jan 13 15:40:01 raspberrypi CRON[9335]: (root) CMD (   PATH="$PATH:/usr/sbin:/usr/local/bin/" pihole updatechecker local)
Jan 13 15:41:27 raspberrypi stubby[19413]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict.
Jan 13 15:41:27 raspberrypi stubby[19413]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict.
Jan 13 15:41:27 raspberrypi stubby[19413]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict.
Jan 13 15:41:27 raspberrypi stubby[19413]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict.

DanSchaper · January 15, 2022, 12:38pm

github.com/getdnsapi/stubby

Strange answer by stubby status

opened 12:10PM - 17 Apr 20 UTC

closed 03:43PM - 06 Oct 20 UTC

Fede068

Hy guys, I've pi-hole with stubby installed on my Raspberrypi 3+ which is workin…g well. I discover some strange notification after checking the status. Please compare as follow: pi@pi-hole:~ $ sudo systemctl status stubby ● stubby.service - stubby DNS resolver Loaded: loaded (/lib/systemd/system/stubby.service; enabled; vendor preset: enabled) Active: active (running) since Wed 2020-04-15 12:19:36 CEST; 23h ago Main PID: 19125 (stubby) Tasks: 1 (limit: 4915) CGroup: /system.slice/stubby.service └─19125 /usr/local/bin/stubby Apr 16 07:32:15 pi-hole stubby[19125]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict. Apr 16 07:32:15 pi-hole stubby[19125]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict. Apr 16 07:32:15 pi-hole stubby[19125]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict. Apr 16 07:32:15 pi-hole stubby[19125]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict. Apr 16 07:32:15 pi-hole stubby[19125]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict. Apr 16 10:51:09 pi-hole stubby[19125]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict. Apr 16 10:51:09 pi-hole stubby[19125]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict. Apr 16 10:51:09 pi-hole stubby[19125]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict. Apr 16 10:51:09 pi-hole stubby[19125]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict. Apr 16 10:51:09 pi-hole stubby[19125]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict. pi@pi-hole:~ $ sudo stubby status [09:44:20.851968] STUBBY: Read config from file /usr/local/etc/stubby/stubby.yml [09:44:20.856403] STUBBY: DNSSEC Validation is OFF [09:44:20.857534] STUBBY: Transport list is: [09:44:20.858306] STUBBY: - TLS [09:44:20.859132] STUBBY: Privacy Usage Profile is Strict (Authentication required) [09:44:20.859943] STUBBY: (NOTE a Strict Profile only applies when TLS is the ONLY transport!!) [09:44:20.860678] STUBBY: Starting DAEMON.... ^C pi@pi-hole:~ $ Why I don´t get the same answer? What does it mean "Could not get qname from ..."? Pls help, thank you in advance!

pi_user · January 15, 2022, 12:46pm

Yes I had also checked that.

The response there mentions this :

Looks like a non-DNS message was received by your Stubby deamon. Downstream that is.

"Downstream that is" - Did they mean upstream?

I mean PiHole > Stubby > NextDNS (I would call NextDNS upstream).

Do they mean there is an non-DNS answer from whatever upstream is being used in this case NextDNS?

And how is it possible that a DNS server return non-DNS response?

From what I know, SERVFAIL / NODATA / NXDOMAIN / CNAME / A / AAAA are all DNS records only.

These are the major ones in my pihole logs, with some more, here is an imgur link.

DanSchaper · January 15, 2022, 12:51pm

Yes

Possibly, you'd have to ask to see.

Maybe it's not a DNS server responding but something else on the same port as Stubby.

You've confused a few things.

SERVFAIL, NODATA, NXDOMAIN are DNS server response statuses.

A, AAA, SRV, SOA.... are DNS record types.

You mention a cleanup process but the one shown in the logs is not Pi-hole, it's the operating system itself. It's doing PHP cleanup. And the timestamps show the php session cleanups are pretty far away from the times that stubby is generating it's messags.

I don't see anything there that would be related to Pi-hole. I'd ask Stubby and/or NextDNS what they have to say.

pi_user · January 15, 2022, 1:04pm

Thanks @DanSchaper

I would ask on the Stubby github issues page now.

DanSchaper · January 15, 2022, 1:06pm

Let us know what you find out...

pi_user · January 15, 2022, 1:42pm

Thanks @DanSchaper for your excellent suggestion in one of the replies above.

Maybe it's not a DNS server responding but something else on the same port as Stubby.

I made Stubby listen on port 5300 and here is a netstat of the same :

 ----- Stubby port  : -----

tcp        0      0 127.0.0.1:5300          0.0.0.0:*               LISTEN      18093/stubby
tcp6       0      0 ::1:5300                :::*                    LISTEN      18093/stubby
udp        0      0 127.0.0.1:5300          0.0.0.0:*                           18093/stubby
udp6       0      0 ::1:5300                :::*                                18093/stubby

I ran a tcpdump to capture packets on both tcp and udp port 5300, the tcp port came empty but there were logs on udp filter on tcpdump when I did use internet for a minute.

It was clear that Stubby was using the UDP port 5300 to listen for DNS queries.

Then I started a netcat udp session using :

nc -u localhost 5300

and wrote random strings and pressed enter 4-5 times.

As soon as I pressed enter for each string, stubby logs went like :

Jan 15 18:42:32 raspberrypi stubby[18093]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict.
Jan 15 18:42:33 raspberrypi stubby[18093]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict.
Jan 15 18:42:34 raspberrypi stubby[18093]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict.
Jan 15 18:43:40 raspberrypi stubby[18093]: Could not get qname from query: A helper function for dicts had a name argument that for a name that is not in the dict.

It is now clear the that non-DNS request query is causing this. There are no other tools / utilities installed on the the Pi machine, so it might be a probe / heartbeat or something else send to port 5300 (not sure though but making this assumption because my netcat test packets didn't get reflected on NextDNS side, nor did any non-DNS test packets sent to local port 53 [pihole dnsmasq] in hopes of successful redirection to 5300 [Stubby] )

Even when these logs appeared, Stubby didn't crash and is continuing to forward and respond with DNS records.

Future debugging should this issue of Stubby crash occurs again will take this course :

Will check syslog for application activities
Will optionally run tcpdump for extended time to replicate this issue to get atleast the port from where alleged non-DNS packets are send
In any case, would present my findings on this thread for future reference / lurkers here.

system · February 5, 2022, 1:42pm

This topic was automatically closed 21 days after the last reply. New replies are no longer allowed.