Unable to auto-update snapshots

stephenw10 · Nov 25, 2014, 12:48 AM

Hmm, well that looks bad. Interestingly I can't access that url either any more. Try again:
https://snapshots.pfsense.org/FreeBSD_releng/10.1/i386/pfSense_HEAD/.updaters/
Could be there were some changes taking place. I don't know though.

Steve

emce · Nov 25, 2014, 1:12 AM

Same issue with: https://snapshots.pfsense.org/FreeBSD_releng/10.1/i386/pfSense_HEAD/.updaters/

I was able to fix fetch by creating a symlink for the root cert bundle:

sudo ln -sf /usr/local/share/certs/ca-root-nss.crt /etc/ssl/cert.pem

fetch -o /dev/null https://snapshots.pfsense.org/FreeBSD_stable/10/i386/pfSense_HEAD/.updaters/version
/dev/null                                     100% of   29  B  123 kBps 00m00s

Unfortunately, this didn't fix auto-update :)

stephenw10 · Nov 25, 2014, 1:22 AM

Hmm, bizzare. :-\ It's still working here on my test box just fine, all four options. There is a redirect in place for 10 stable to 10.1 releng:

[2.2-BETA][root@xtm5.localdomain]/root: fetch -o /dev/null http://snapshots.pfsense.org/FreeBSD_stable/10/i386/pfSense_HEAD/.updaters/version
/dev/null                                     100% of   29  B  300 kBps 00m00s
[2.2-BETA][root@xtm5.localdomain]/root: fetch -o /dev/null https://snapshots.pfsense.org/FreeBSD_stable/10/i386/pfSense_HEAD/.updaters/version
/dev/null                                     100% of   29  B  298 kBps 00m00s
[2.2-BETA][root@xtm5.localdomain]/root: fetch -o /dev/null https://snapshots.pfsense.org/FreeBSD_releng/10.1/i386/pfSense_HEAD/.updaters/version
/dev/null                                     100% of   29  B  307 kBps 00m00s
[2.2-BETA][root@xtm5.localdomain]/root: fetch -o /dev/null http://snapshots.pfsense.org/FreeBSD_releng/10.1/i386/pfSense_HEAD/.updaters/version
/dev/null                                     100% of   29  B  209 kBps 00m00s

There have been cert problems before but usually affecting everything. Do you have a bad system date that's rendering the cert invalid?
I'd be tempted to re-install at thus point.

Steve

emce · Nov 25, 2014, 1:26 AM

I just manually installed the latest snapshot. Perhaps a contributor turned on some additional debugging in the updater widget, but it spit out the following output:

2.2-BETA (i386)
built on Mon Nov 24 16:50:47 CST 2014
FreeBSD 10.1-RELEASE
…........ Warning: Cannot modify header information - headers already sent by (output started at /etc/inc/config.inc:45) in /usr/local/www/guiconfig.inc on line 48 Warning: Cannot modify header information - headers already sent by (output started at /etc/inc/config.inc:45) in /usr/local/www/guiconfig.inc on line 49 Warning: Cannot modify header information - headers already sent by (output started at /etc/inc/config.inc:45) in /usr/local/www/guiconfig.inc on line 50 Warning: Cannot modify header information - headers already sent by (output started at /etc/inc/config.inc:45) in /usr/local/www/guiconfig.inc on line 51 Warning: Cannot modify header information - headers already sent by (output started at /etc/inc/config.inc:45) in /usr/local/www/guiconfig.inc on line 52 Warning: Cannot modify header information - headers already sent by (output started at /etc/inc/config.inc:45) in /usr/local/www/guiconfig.inc on line 55 Warning: session_start(): Cannot send session cache limiter - headers already sent (output started at /etc/inc/config.inc:45) in /etc/inc/auth.inc on line 1362

Unable to check for updates.

emce · Nov 25, 2014, 1:49 AM

I think I finally figured it out… I'm using the new unbound DNS Resolver, and had the following option unchecked under System->General Setup:

-Do not use the DNS Forwarder as a DNS server for the firewall

I noticed I was getting a failed resolution for snapshots.pfsense.org, so I enabled that option and it started working correctly under the System->Firmware->Auto Update tab. I'm still getting the extra debug output in the System information widget under "Version", but I think that's actually a PHP error in the latest build.

I'll report back if it succeeds in finding the next update. Thanks a lot for your help!

emce · Nov 25, 2014, 10:44 PM

FYI - this did end up fixing the issue.

MikeV7896 · Nov 26, 2014, 12:35 AM

Same issue as emce, and unchecking that same box worked to fix it for me as well.

jimp · Nov 26, 2014, 12:39 AM

Did you have any name servers filled in under System > General?

emce · Nov 26, 2014, 12:41 AM

@jimp:

Did you have any name servers filled in under System > General?

I do. I'm using Google's servers, followed by those of my ISP.

On a related note, I'm continuing to see the erroneous output in the Version section of the System Information widget:

2.2-BETA (i386)
built on Tue Nov 25 11:51:07 CST 2014
FreeBSD 10.1-RELEASE
…........ Warning: Cannot modify header information - headers already sent by (output started at /etc/inc/config.inc:45) in /usr/local/www/guiconfig.inc on line 48 Warning: Cannot modify header information - headers already sent by (output started at /etc/inc/config.inc:45) in /usr/local/www/guiconfig.inc on line 49 Warning: Cannot modify header information - headers already sent by (output started at /etc/inc/config.inc:45) in /usr/local/www/guiconfig.inc on line 50 Warning: Cannot modify header information - headers already sent by (output started at /etc/inc/config.inc:45) in /usr/local/www/guiconfig.inc on line 51 Warning: Cannot modify header information - headers already sent by (output started at /etc/inc/config.inc:45) in /usr/local/www/guiconfig.inc on line 52 Warning: Cannot modify header information - headers already sent by (output started at /etc/inc/config.inc:45) in /usr/local/www/guiconfig.inc on line 55 Warning: session_start(): Cannot send session cache limiter - headers already sent (output started at /etc/inc/config.inc:45) in /etc/inc/auth.inc on line 1362

jimp · Nov 26, 2014, 12:44 AM

Can you check /etc/resolv.conf to see if the name servers are actually there?

emce · Nov 26, 2014, 12:46 AM

Sure thing. Here's the contents:

$ cat /etc/resolv.conf
search <mydomain>.com
nameserver 8.8.8.8
nameserver 8.8.4.4
nameserver 75.75.75.75
nameserver 75.75.76.76</mydomain>

jimp · Nov 26, 2014, 12:52 AM

In that case it should have been able to resolve, unless you can't reach any of those servers

emce · Nov 26, 2014, 12:54 AM

I've tried toggling the "Do not use the DNS Forwarder as a DNS server for the firewall" option on and off, and can successfully reproduce the issue. I don't seem to be having any other resolution issues off of this box at the moment. Definitely odd.

cmb · Nov 26, 2014, 1:05 AM

anything relevant in your resolver log? Status>System logs, Resolver.

What does the output of:

sockstat -4 | grep 53

run from a command prompt show?

MikeV7896 · Nov 26, 2014, 1:08 AM

Ok… scratch me from having the problem. I was actually having an issue with unbound (see that thread). I just unchecked that setting and it's still checking for updates.

emce · Nov 26, 2014, 1:21 AM

I'm assuming you'd like this output from the "error" state, ie, "Do not use the DNS Forwarder as a DNS server for the firewall" is toggled off for the following…

Current sockstat output:

$ sockstat -4 | grep 53
unbound  unbound    67721 10 udp4   10.0.0.1:53           *:*
unbound  unbound    67721 11 tcp4   10.0.0.1:53           *:*
unbound  unbound    67721 12 tcp4   127.0.0.1:953         *:*
root     miniupnpd  40431 16 udp4   10.0.0.1:5351         *:*
?        ?          ?     ?  tcp4   <myip>:53366   192.12.94.30:53
?        ?          ?     ?  tcp4   <myip>:12766   192.41.162.30:53</myip></myip>

I didn't notice anything relevant in the resolver log, but this basic block is repeated:

Nov 25 18:18:32	unbound: [1038:0] info: start of service (unbound 1.4.22).
Nov 25 18:18:32	unbound: [1038:0] notice: init module 1: iterator
Nov 25 18:18:32	unbound: [1038:0] notice: init module 0: validator
Nov 25 18:18:32	unbound: [1038:0] notice: Restart of unbound 1.4.22.
Nov 25 18:18:32	unbound: [1038:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
Nov 25 18:18:32	unbound: [1038:0] info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch
Nov 25 18:18:32	unbound: [1038:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
Nov 25 18:18:32	unbound: [1038:0] info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch
Nov 25 18:18:32	unbound: [1038:0] info: service stopped (unbound 1.4.22).
Nov 25 18:18:31	unbound: [1038:0] info: start of service (unbound 1.4.22).
Nov 25 18:18:31	unbound: [1038:0] notice: init module 1: iterator
Nov 25 18:18:31	unbound: [1038:0] notice: init module 0: validator
Nov 25 18:18:31	unbound: [1038:0] notice: Restart of unbound 1.4.22.
Nov 25 18:18:31	unbound: [1038:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
Nov 25 18:18:31	unbound: [1038:0] info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch
Nov 25 18:18:31	unbound: [1038:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
Nov 25 18:18:31	unbound: [1038:0] info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch
Nov 25 18:18:31	unbound: [1038:0] info: service stopped (unbound 1.4.22).
Nov 25 18:18:31	unbound: [1038:0] info: start of service (unbound 1.4.22).
Nov 25 18:18:31	unbound: [1038:0] notice: init module 1: iterator
Nov 25 18:18:31	unbound: [1038:0] notice: init module 0: validator
Nov 25 18:18:30	unbound: [67721:0] info: 1.000000 2.000000 6
Nov 25 18:18:30	unbound: [67721:0] info: 0.524288 1.000000 14
Nov 25 18:18:30	unbound: [67721:0] info: 0.262144 0.524288 6
Nov 25 18:18:30	unbound: [67721:0] info: 0.131072 0.262144 2
Nov 25 18:18:30	unbound: [67721:0] info: 0.065536 0.131072 13
Nov 25 18:18:30	unbound: [67721:0] info: 0.032768 0.065536 15
Nov 25 18:18:30	unbound: [67721:0] info: 0.016384 0.032768 10
Nov 25 18:18:30	unbound: [67721:0] info: 0.008192 0.016384 2
Nov 25 18:18:30	unbound: [67721:0] info: 0.000000 0.000001 5
Nov 25 18:18:30	unbound: [67721:0] info: lower(secs) upper(secs) recursions
Nov 25 18:18:30	unbound: [67721:0] info: [25%]=0.0354987 median[50%]=0.0882215 [75%]=0.583752
Nov 25 18:18:30	unbound: [67721:0] info: histogram of recursion processing times
Nov 25 18:18:30	unbound: [67721:0] info: average recursion processing time 0.301498 sec
Nov 25 18:18:30	unbound: [67721:0] info: server stats for thread 1: requestlist max 19 avg 3.60811 exceeded 0 jostled 0
Nov 25 18:18:30	unbound: [67721:0] info: server stats for thread 1: 87 queries, 14 answers from cache, 73 recursions, 1 prefetch

cmb · Nov 26, 2014, 1:50 AM

You're not binding to localhost, so it fails when you tell it to use localhost.

That should skip 127.0.0.1 being added to resolv.conf in that circumstance to avoid breaking with such misconfigurations. There's a problem of some sort there, looking.

phil.davis · Nov 26, 2014, 1:53 AM

I didn't notice anything relevant in the resolver log, but this basic block is repeated:

Just a note to say that this seems to be normal behavior on startup. I guess it starts and then sends it SIGHUP or whatever messages that are causing it to reload (what would be an unchanged config at that point). I don't think any harm is done. A side-issue to the issue of this thread.
Ref this post: https://forum.pfsense.org/index.php?topic=84474.0

emce · Nov 26, 2014, 2:19 AM

@cmb:

You're not binding to localhost, so it fails when you tell it to use localhost
…

I've updated the resolver to bind to localhost as well as the LAN IP and it did correct the issue. I don't remember modifying that, but apparently I did at some point.

Thanks!

cmb · Nov 26, 2014, 3:16 AM

@cmb:

You're not binding to localhost, so it fails when you tell it to use localhost.

That should skip 127.0.0.1 being added to resolv.conf in that circumstance to avoid breaking with such misconfigurations.

That problem is fixed.

While there, I also added input validation so if you have the system configured in such a way that 127.0.0.1 would normally end up in resolv.conf, it forces you to pick Localhost in the bindings list in Unbound or check "Do not use the DNS Forwarder as a DNS server for the firewall" to allow it to be omitted.