Some sites take one minute or longer to load with Pi-hole after upgrade

johlym · December 31, 2016, 1:50am

I didn't start noticing this until after I upgraded from 1.9.5 to 2.10.2, a couple days ago.

What I'm seeing, on all devices on my network, is some sites start loading, the page starts rendering partially, and and gets held up while the blocked assets time out. This didn't use to happen, they were just actively refused. I'm wondering what might have changed to prevent blocked URLs time out instead of be refused outright.

These slow loading pages are only appearing in cases where there are blocking javascript assets are being blocked. Non-blocking assets don't hold up the page load.

Debug token: lrtk735p6u

Here's a visual example of these long loads/eventual timeouts featuring assets expected to be blocked (not timed out).

DanSchaper · December 31, 2016, 1:57am

Which site is that screencap from? I'd like to see if I can trace this down to IPv6 or not. (I'm wondering if the clients are getting an IPv6 address from the dnsmasq process, and if lighttpd isn't listening on that same address, then instead of getting the 404 immediately, it would timeout and hang up the process.)

johlym · December 31, 2016, 2:03am

Hi @DanSchaper, in this particular case, it's https://500px.com. Any of the pages on their site will trigger a request for (and eventual timeout of) at least cdn.optimizely.com and sometimes csi.gstatic.com as well.

A direct curl request shows a quick refusal:

$ curl https://cdn.optimizely.com
curl: (7) Failed to connect to cdn.optimizely.com port 443: Connection refused

DanSchaper · December 31, 2016, 2:12am

Thanks, a couple of checks, if you wouldn't mind:

dig cdn.optimizely.com
dig -6 cdn.optimizely.com
curl -I cdn.opmizely.com
curl -I https://cdn.optimizely.com

johlym · December 31, 2016, 2:32am

@DanSchaper no problem.

➜  ~ dig cdn.optimizely.com

; <<>> DiG 9.8.3-P1 <<>> cdn.optimizely.com
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 56774
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;cdn.optimizely.com.		IN	A

;; ANSWER SECTION:
cdn.optimizely.com.	300	IN	A	172.16.1.3

;; Query time: 5 msec
;; SERVER: 172.16.100.6#53(172.16.100.6)
;; WHEN: Fri Dec 30 18:21:08 2016
;; MSG SIZE  rcvd: 52

➜  ~ dig -6 cdn.optimizely.com

; <<>> DiG 9.8.3-P1 <<>> -6 cdn.optimizely.com
;; global options: +cmd
;; connection timed out; no servers could be reached

➜  ~ curl -I cdn.optimizely.com
curl: (7) Failed to connect to cdn.optimizely.com port 80: Operation timed out

➜  ~ curl -I https://cdn.optimizely.com
curl: (7) Failed to connect to cdn.optimizely.com port 443: Operation timed out

So an interesting bit of information... those ^ were done on a client device. On the Pi running Pi-hole itself, I get this:

pi@rpi3-01:~ $ dig cdn.optimizely.com

; <<>> DiG 9.9.5-9+deb8u8-Raspbian <<>> cdn.optimizely.com
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 51555
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
;; QUESTION SECTION:
;cdn.optimizely.com.		IN	A

;; ANSWER SECTION:
cdn.optimizely.com.	300	IN	A	172.16.1.3

;; Query time: 0 msec
;; SERVER: 127.0.0.1#53(127.0.0.1)
;; WHEN: Fri Dec 30 18:27:47 PST 2016
;; MSG SIZE  rcvd: 63

pi@rpi3-01:~ $ dig -6 cdn.optimizely.com

; <<>> DiG 9.9.5-9+deb8u8-Raspbian <<>> -6 cdn.optimizely.com
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 9661
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
;; QUESTION SECTION:
;cdn.optimizely.com.		IN	A

;; ANSWER SECTION:
cdn.optimizely.com.	300	IN	A	172.16.1.3

;; Query time: 0 msec
;; SERVER: ::1#53(::1)
;; WHEN: Fri Dec 30 18:28:13 PST 2016
;; MSG SIZE  rcvd: 63

pi@rpi3-01:~ $ curl -I cdn.optimizely.com
HTTP/1.1 200 OK
X-Pi-hole: A black hole for Internet advertisements.
Content-Type: text/html
Accept-Ranges: bytes
ETag: "421379974"
Last-Modified: Tue, 13 Sep 2016 21:57:21 GMT
Content-Length: 78
Date: Sat, 31 Dec 2016 02:28:36 GMT
Server: lighttpd/1.4.35

pi@rpi3-01:~ $ curl -I https://cdn.optimizely.com
curl: (7) Failed to connect to cdn.optimizely.com port 443: Connection refused

My router it set to give out the Pi's IP address as the sole DNS source, though the Pi is pointed at itself using the localhost address 127.0.0.1:

;; SERVER: 127.0.0.1#53(127.0.0.1)
;; SERVER: ::1#53(::1)

Not sure if that matters. I don't remember what it was set to before the upgrade.

DanSchaper · December 31, 2016, 2:44am

And on the client machine, ip a for the interface addresses and cat /etc/resolv.conf to see what its using as the DNS server?

And just to check and see, can you run sudo iptables -L on the Pi-hole and see if there is a firewall policy set to DROP.

I do notice from the first dig on the client that the response came from 172.16.100.6, but that doesn't appear to be an address related to the Pi-hole itself.

DanSchaper · December 31, 2016, 2:46am

Ah, the Pi-hole has two 172 addresses. Try a sudo netstat -tulpn and lets see if lighttpd is running on all interfaces/addresses or if it's not listening on one of them, leading to a timeout.

jacob.salmela · December 31, 2016, 3:49am

So I've seen this behavior on occasion, too.

I get the same results as @johlym from all the commands, except I get a different error code on the last two commands.

curl -I cdn.opmizely.com
curl: (6) Could not resolve host: cdn.opmizely.com

and

curl -I https://cdn.optimizely.com
curl: (35) Server aborted the SSL handshake

Here's my sudo netstat -tulpn

tcp        0      0 0.0.0.0:80              0.0.0.0:*               LISTEN      26664/lighttpd  
tcp6       0      0 :::80                   :::*                    LISTEN      26664/lighttpd

DanSchaper · December 31, 2016, 3:56am

Are you both on Macs? Trying with a couple of actual Pi Zero's to debug, and on Fedora fullstack IPv4/6:

 ~ curl -I cdn.optimizely.com                                           Fri 30 Dec 2016 07:50:47 PM PST
HTTP/1.1 404 Not Found
X-Pi-hole: A black hole for Internet advertisements.
Content-Type: text/html
Content-Length: 345
Date: Sat, 31 Dec 2016 03:50:53 GMT
Server: lighttpd/1.4.35

 ~ curl -I https://cdn.optimizely.com                    
curl: (7) Failed to connect to cdn.optimizely.com port 443: No route to host

; <<>> DiG 9.10.4-P4-RedHat-9.10.4-2.P4.fc25 <<>> -6 cdn.optimizely.com
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 55786
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
;; QUESTION SECTION:
;cdn.optimizely.com.		IN	A

;; ANSWER SECTION:
cdn.optimizely.com.	33	IN	A	192.168.30.2

;; Query time: 1 msec
;; SERVER: fe80::a021:b7ff:fe9b:4b24%2#53(fe80::a021:b7ff:fe9b:4b24%2)
;; WHEN: Fri Dec 30 19:55:21 PST 2016
;; MSG SIZE  rcvd: 63

 ~ dig cdn.optimizely.com

; <<>> DiG 9.10.4-P4-RedHat-9.10.4-2.P4.fc25 <<>> cdn.optimizely.com
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 22661
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
;; QUESTION SECTION:
;cdn.optimizely.com.		IN	A

;; ANSWER SECTION:
cdn.optimizely.com.	24	IN	A	192.168.30.2

;; Query time: 1 msec
;; SERVER: 192.168.1.1#53(192.168.1.1)
;; WHEN: Fri Dec 30 19:55:30 PST 2016
;; MSG SIZE  rcvd: 63

jacob.salmela · December 31, 2016, 4:07am

Well, you know me...of course I'm on a Mac .

I'm on v4/v6 over here, too.

I'll spin up different client VM and see what results from that.

DanSchaper · December 31, 2016, 4:15am

Let me know, there's a couple of idea's that I have that may be in play, at least I'm getting some more test cases to run through the debugger and the eventual test rigs.

jacob.salmela · December 31, 2016, 4:18am

Good thing you passed warp core diagnostics 101... . Those debugging skills are being put to the test!

I'll have some more info for you soon.

jacob.salmela · December 31, 2016, 4:27am

From an Ubuntu machine:

~$ curl -I cdn.opmizely.com
curl: (6) Could not resolve host: cdn.opmizely.com

~$ curl -I https://cdn.optimizely.com
curl: (7) Failed to connect to cdn.optimizely.com port 443: Connection refused

~$ dig cdn.optimizely.com

; <<>> DiG 9.10.3-P4-Ubuntu <<>> cdn.optimizely.com
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 1073
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
;; QUESTION SECTION:
;cdn.optimizely.com.		IN	A

;; ANSWER SECTION:
cdn.optimizely.com.	300	IN	A	192.168.1.100

;; Query time: 5 msec
;; SERVER: 10.211.55.1#53(10.211.55.1)
;; WHEN: Fri Dec 30 22:26:06 CST 2016
;; MSG SIZE  rcvd: 63

~$ dig -6 cdn.optimizely.com

; <<>> DiG 9.10.3-P4-Ubuntu <<>> -6 cdn.optimizely.com
;; global options: +cmd
;; connection timed out; no servers could be reached

DanSchaper · December 31, 2016, 4:38am

Wow, what's the /etc/resolv.conf say?

johlym · December 31, 2016, 4:59am

Let's do this...

Since I'm on a mac, ip isn't a thing out of the box, so here's this:

en0: flags=8863<UP,BROADCAST,SMART,RUNNING,SIMPLEX,MULTICAST> mtu 1500
	ether a4:5e:60:c7:a6:87
	inet6 fe80::10db:f63b:8903:7524%en0 prefixlen 64 secured scopeid 0x4
	inet 172.16.100.4 netmask 0xffffff00 broadcast 172.16.100.255
	nd6 options=201<PERFORMNUD,DAD>
	media: autoselect
	status: active

and

➜  ~ cat /etc/resolv.conf
nameserver 172.16.100.6

pi@rpi3-01:~ $ sudo iptables -L
Chain INPUT (policy ACCEPT)
target     prot opt source               destination
ACCEPT     tcp  --  anywhere             anywhere             tcp dpt:http
ACCEPT     tcp  --  anywhere             anywhere             tcp dpt:domain
ACCEPT     udp  --  anywhere             anywhere             udp dpt:domain

Chain FORWARD (policy ACCEPT)
target     prot opt source               destination

Chain OUTPUT (policy ACCEPT)
target     prot opt source               destination

That's an interesting twist because 172.16.100.6 is the IP address of the Pi-hole. I'm not sure where 172.16.1.3 came from as a response IP because my entire network is under the 172.16.100.0/24 subnet. I don't have it set under /etc/network/interfaces and my router doesn't 1) give out addressed in 172.16.1.x nor 2) I have a static lease set up to issue that address.

it does turn look like the Pi has two IP addresses

2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP group default qlen 1000
    link/ether b8:27:eb:8c:68:f0 brd ff:ff:ff:ff:ff:ff
    inet 172.16.1.3/24 brd 172.16.1.255 scope global eth0
       valid_lft forever preferred_lft forever
    inet 172.16.100.6/24 brd 172.16.100.255 scope global eth0
       valid_lft forever preferred_lft forever
    inet6 fe80::112e:dacd:2b27:bd48/64 scope link
       valid_lft forever preferred_lft forever

though lighttpd is running on:

pi@rpi3-01:~ $ sudo netstat -tulpn | grep lighttpd
tcp        0      0 0.0.0.0:80              0.0.0.0:*               LISTEN      22348/lighttpd
tcp6       0      0 :::80                   :::*                    LISTEN      22348/lighttpd

So looking at all this, I deleted the 172.16.1.3 address that was hanging around, but now how do I convince Pi-hole to stop dishing it out as the address? Is that in a config file somewhere? I'm wondering, since 172.16.1.3 was the first IP address in the list, is it possible that Pi-hole automatically assumed that's the address it should be giving out when clients make a DNS request?

-J

DanSchaper · December 31, 2016, 5:03am

The short way would be to edit the /etc/pihole/setupVars.conf file and change out the IPv4 address. Then pihole -g should update everything, you can check with a quick head /etc/pihole/gravity.list and see what address is listed for the IP. If that doesn't work, then rm /etc/pihole/setupVars.conf followed by a pihole -r would be closest to a reinstall. But try the manual edit first, and then check your /etc/dhcpcd.conf and look to the end of the file to make sure the static address is set correctly and the phantom address doesn't show up again on a reboot of the Pi.

johlym · December 31, 2016, 5:11am

Huh.

IPV4_ADDRESS=172.16.1.3/24

Well dang.

Also found that address in /etc/dhcpdc.conf. Lobbed that off, too.

Ran pihole -g then head /etc/pihole/gravity.list and the records look to be updated:

172.16.100.6 0000mps.webpreview.dsl.net
[...]

So... checking in from the client:

➜  ~ dig cdn.optimizely.com
; <<>> DiG 9.8.3-P1 <<>> cdn.optimizely.com
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 52541
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;cdn.optimizely.com.		IN	A

;; ANSWER SECTION:
cdn.optimizely.com.	300	IN	A	172.16.100.6

;; Query time: 2 msec
;; SERVER: 172.16.100.6#53(172.16.100.6)
;; WHEN: Fri Dec 30 21:10:05 2016
;; MSG SIZE  rcvd: 52

And it looks like I'm in business.

So... The theme of this story is: Pi-hole picked the wrong address (one I didn't know I had!) and was dishing that out, instead.

1 vote for being able to update the configVars.conf settings from the UI, or something like that.

This is crazy because this didn't show up until after the update...

DanSchaper · December 31, 2016, 5:19am

Well, it has given me a couple more test scenarios to run through with the debugger on it's rewrite. We do have a Feature Request section that you can put in a post for being able to see/edit setupVars though in browser editing may be harder to pull off. There are a few changes in the IP address detection routine that are either in development or slated to go in development, so I'll brush through them and see if there's a chance to detect and avert this kind of situation in the future. But glad we were able to solve this one, and get you back to where you should be. Now for Jacob...

DanSchaper · December 31, 2016, 5:21am

Yeah, I think the new code Smarter pick of IPv4 address by dschaper · Pull Request #1037 · pi-hole/pi-hole · GitHub will check for that, the address now has to be at least listed on the default interface as the route to the rest of the world, and the .1 address wouldn't have passed that test.

johlym · December 31, 2016, 5:33am

That's fair. I suppose the check for a valid route would also suffice. I can't imagine a scenario where I would have checked for the bogus IP and setting on my own.