Lots of logging

Unbound
1

I'm running unbound 1.4.16 on FreeBSD 8.4.

When the server starts up, unbound floods the log with error messages,
a sample:

2013-06-17T12:08:13.885341-0400 oneyou unbound: [1090:0] notice: sendto
failed: Operation not permitted

2013-06-17T12:08:13.885404-0400 oneyou unbound: [1090:0] notice: remote
address is 2001:7fd::1 port 53

2013-06-17T12:08:13.885454-0400 oneyou unbound: [1090:0] notice: sendto
failed: Operation not permitted

2013-06-17T12:08:13.885505-0400 oneyou unbound: [1090:0] notice: remote
address is 2001:500:2f::f port 53

2013-06-17T12:08:13.885564-0400 oneyou unbound: [1090:0] notice: sendto
failed: Operation not permitted

2013-06-17T12:08:13.885600-0400 oneyou unbound: [1090:0] notice: remote
address is 192.203.230.10 port 53

2013-06-17T12:08:13.885668-0400 oneyou unbound: [1090:0] notice: sendto
failed: Operation not permitted

2013-06-17T12:08:13.885703-0400 oneyou unbound: [1090:0] notice: remote
address is 192.203.230.10 port 53

2013-06-17T12:08:13.885768-0400 oneyou unbound: [1090:0] notice: sendto
failed: Operation not permitted

2013-06-17T12:08:13.885803-0400 oneyou unbound: [1090:0] notice: remote
address is 192.33.4.12 port 53

2013-06-17T12:08:13.885871-0400 oneyou unbound: [1090:0] notice: sendto
failed: Operation not permitted

2013-06-17T12:08:13.885906-0400 oneyou unbound: [1090:0] notice: remote
address is 2001:503:ba3e::2:30 port 53

2013-06-17T12:08:13.885976-0400 oneyou unbound: [1090:0] notice: sendto
failed: Operation not permitted

2013-06-17T12:08:13.886011-0400 oneyou unbound: [1090:0] notice: remote
address is 2001:500:2d::d port 53

2013-06-17T12:08:13.886079-0400 oneyou unbound: [1090:0] notice: sendto
failed: Operation not permitted

2013-06-17T12:08:13.886138-0400 oneyou unbound: [1090:0] notice: remote
address is 199.7.83.42 port 53

2013-06-17T12:08:13.886187-0400 oneyou unbound: [1090:0] notice: sendto
failed: Operation not permitted

2013-06-17T12:08:13.886221-0400 oneyou unbound: [1090:0] notice: remote
address is 193.0.14.129 port 53

2013-06-17T12:08:13.886286-0400 oneyou unbound: [1090:0] notice: sendto
failed: Operation not permitted

2013-06-17T12:08:13.886321-0400 oneyou unbound: [1090:0] notice: remote
address is 192.112.36.4 port 53

2013-06-17T12:08:13.886384-0400 oneyou unbound: [1090:0] notice: sendto
failed: Operation not permitted

That's a millisecond's worth of log records.

Why is unbound doing this? What is unbound trying to tell me?

2

Traditionally questions like this will include the config file you are
using. I imagine it has to do with the verbosity of your logging
config statements.

4

Hi Mike,

The operating system tells unbound that it cannot send to a 'normal'
IP address. (unbound has do-not-query and access-control in its
config to block IPs you do not like).

If you have a strange setup and traffic from clients not on localhost
arrives to 127.0.0.1 and unbound tries to answer back, then this error
is normal for trying to send to 192... with source address 127.0.0.1.

Otherwise, this must be traffic that unbound sends to nameservers
('upstream'). If you dig @192.203.230.10 , is that also operation not
permitted?

This error is not throttled by verbosity, because it is likely a local
misconfiguration. The OS disallows network access to unbound ...

Best regards,
   Wouter

6

Hi Mike,

>-----BEGIN PGP SIGNED MESSAGE----- |Hash: SHA1 | |Hi Mike, | |The
operating system tells unbound that it cannot send to a 'normal'
>IP address. (unbound has do-not-query and access-control in its
>config to block IPs you do not like). | |If you have a strange
setup and traffic from clients not on localhost |arrives to
127.0.0.1 and unbound tries to answer back, then this error |is
normal for trying to send to 192... with source address 127.0.0.1.
> >Otherwise, this must be traffic that unbound sends to
nameservers |('upstream'). If you dig @192.203.230.10 , is that
also operation not |permitted? | |This error is not throttled by
verbosity, because it is likely a local |misconfiguration. The OS
disallows network access to unbound ... | |Best regards, |
Wouter =============

Hi Wouter,

I noticed the same excessive logging one time on another server
(FreeBSD 9.1, unbound 1.4.18). I was doing some minor rack
reconfiguration, and I unplugged the network cable from the server
running unbound for a couple of seconds. I saw a similar flood of
log messages during the time that the network cable was unplugged.

In the case I posted yesterday, perhaps the network was not yet
available when unbound started up, and for the two seconds until
the network became available, unbound flooded the log with error
messages. After those two seconds, unbound's logging was fine, and
as expected.

So in my experiences, it appears that unbound does the excessive
logging when DNS queries are being made and the network goes away,
or is not available.

My question through all this is: what is an appropriate volume of
logging for a program when that program experiences a network
issue? In my opinion a logging rate of 20 messages in a millisecond
(20,000 messages per second) might be a bit excessive. A single
"no network interface available", or something along those lines,
might be more appropriate and helpful.

That is excessive. So, the message is printed if you set verbosity
higher (2 = per query verbose). If people need to debug they try to
set verbosity higher and can then get a dose of these errors if they
have them. (you can briefly set verbosity higher and lower using
unbound-control).

Best regards,
   Wouter