Enthusiastic logging when interface goes away

[Mike1]

I use unbound as a resolver on my home network. I've been very happy
with how well it works. Except in one area.

Unbound seems to flood the log file when the network interface goes
away, e.g., my ISP does some maintenance in the wee hours of the morning.

The log records occur at a rate of about one THOUSAND per second. When
there's a 15 minute outage, ... well, that's a log of log records.

Two questions:

1) Is there a configuration parameter that cools down unbound's
enthusiasm for extreme logging rates?

2) More of a curiosity - what was the use case that cause this extreme
logging rate to be coded into unbound?

What I'd prefer to see would be something along the lines of:

- a log record when the problem initially occurs
- a log record every minute or so as the problem persists
- a log record showing that the problem went away and normal operation
has returned.

For me, that'd be a lot more helpful.

Below is a very short excerpt of the log records I see in a log file:
(first column is hhmmss.milliseconds)

165518.521 error: can't bind socket: Can't assign requested address for
165518.521 error: can't bind socket: Can't assign requested address for
165518.521 error: can't bind socket: Can't assign requested address for
165518.522 error: can't bind socket: Can't assign requested address for
165518.522 error: can't bind socket: Can't assign requested address for
165518.522 error: can't bind socket: Can't assign requested address for
165518.522 error: can't bind socket: Can't assign requested address for
165518.522 error: can't bind socket: Can't assign requested address for
165518.522 error: can't bind socket: Can't assign requested address for
165518.522 error: can't bind socket: Can't assign requested address for
165518.522 error: can't bind socket: Can't assign requested address for
165518.522 error: can't bind socket: Can't assign requested address for
165518.522 error: can't bind socket: Can't assign requested address for
165518.522 error: can't bind socket: Can't assign requested address for
165518.522 error: can't bind socket: Can't assign requested address for
165518.523 error: can't bind socket: Can't assign requested address for
165518.523 error: can't bind socket: Can't assign requested address for
165518.523 error: can't bind socket: Can't assign requested address for
165518.523 error: can't bind socket: Can't assign requested address for
165518.523 error: can't bind socket: Can't assign requested address for
165518.523 error: can't bind socket: Can't assign requested address for
165518.523 error: can't bind socket: Can't assign requested address for
165518.524 error: can't bind socket: Can't assign requested address for
165518.524 error: can't bind socket: Can't assign requested address for
165518.524 error: can't bind socket: Can't assign requested address for
165518.524 error: can't bind socket: Can't assign requested address for
165518.524 error: can't bind socket: Can't assign requested address for
165518.524 error: can't bind socket: Can't assign requested address for
165518.524 error: can't bind socket: Can't assign requested address for
165518.524 error: can't bind socket: Can't assign requested address for
165518.524 error: can't bind socket: Can't assign requested address for
165518.525 error: can't bind socket: Can't assign requested address for
165518.525 error: can't bind socket: Can't assign requested address for
165518.525 error: can't bind socket: Can't assign requested address for
165518.525 error: can't bind socket: Can't assign requested address for
165518.525 error: can't bind socket: Can't assign requested address for
165518.525 error: can't bind socket: Can't assign requested address for
165518.526 error: can't bind socket: Can't assign requested address for
165518.526 error: can't bind socket: Can't assign requested address for
165518.526 error: can't bind socket: Can't assign requested address for
165518.526 error: can't bind socket: Can't assign requested address for
165518.526 error: can't bind socket: Can't assign requested address for
165518.526 error: can't bind socket: Can't assign requested address for
165518.526 error: can't bind socket: Can't assign requested address for
165518.526 error: can't bind socket: Can't assign requested address for
165518.526 error: can't bind socket: Can't assign requested address for
165518.527 error: can't bind socket: Can't assign requested address for
165518.527 error: can't bind socket: Can't assign requested address for
165518.527 error: can't bind socket: Can't assign requested address for
165518.527 error: can't bind socket: Can't assign requested address for
165518.527 error: can't bind socket: Can't assign requested address for
165518.527 error: can't bind socket: Can't assign requested address for
165518.527 error: can't bind socket: Can't assign requested address for
165518.527 error: can't bind socket: Can't assign requested address for
165518.527 error: can't bind socket: Can't assign requested address for
165518.527 error: can't bind socket: Can't assign requested address for
165518.527 error: can't bind socket: Can't assign requested address for
165518.528 error: can't bind socket: Can't assign requested address for
165518.528 error: can't bind socket: Can't assign requested address for
165518.528 error: can't bind socket: Can't assign requested address for
165518.528 error: can't bind socket: Can't assign requested address for
165518.528 error: can't bind socket: Can't assign requested address for
165518.528 error: can't bind socket: Can't assign requested address for
165518.528 error: can't bind socket: Can't assign requested address for
165518.529 error: can't bind socket: Can't assign requested address for
165518.529 error: can't bind socket: Can't assign requested address for
165518.529 error: can't bind socket: Can't assign requested address for
165518.529 error: can't bind socket: Can't assign requested address for
165518.529 error: can't bind socket: Can't assign requested address for
165518.529 error: can't bind socket: Can't assign requested address for
165518.529 error: can't bind socket: Can't assign requested address for
165518.529 error: can't bind socket: Can't assign requested address for
165518.529 error: can't bind socket: Can't assign requested address for
165518.529 error: can't bind socket: Can't assign requested address for
165518.529 error: can't bind socket: Can't assign requested address for
165518.529 error: can't bind socket: Can't assign requested address for
165518.529 error: can't bind socket: Can't assign requested address for
165518.529 error: can't bind socket: Can't assign requested address for
165518.530 error: can't bind socket: Can't assign requested address for
165518.530 error: can't bind socket: Can't assign requested address for
165518.530 error: can't bind socket: Can't assign requested address for
165518.530 error: can't bind socket: Can't assign requested address for
165518.530 error: can't bind socket: Can't assign requested address for
165518.530 error: can't bind socket: Can't assign requested address for
165518.530 error: can't bind socket: Can't assign requested address for
165518.530 error: can't bind socket: Can't assign requested address for
165518.530 error: can't bind socket: Can't assign requested address for
165518.530 error: can't bind socket: Can't assign requested address for
165518.531 error: can't bind socket: Can't assign requested address for
165518.531 error: can't bind socket: Can't assign requested address for
165518.531 error: can't bind socket: Can't assign requested address for
165518.531 error: can't bind socket: Can't assign requested address for
165518.531 error: can't bind socket: Can't assign requested address for
165518.531 error: can't bind socket: Can't assign requested address for
165518.531 error: can't bind socket: Can't assign requested address for
165518.532 error: can't bind socket: Can't assign requested address for
165518.532 error: can't bind socket: Can't assign requested address for
165518.532 error: can't bind socket: Can't assign requested address for
165518.532 error: can't bind socket: Can't assign requested address for
165518.532 error: can't bind socket: Can't assign requested address for
165518.532 error: can't bind socket: Can't assign requested address for
165518.532 error: can't bind socket: Can't assign requested address for
165518.532 error: can't bind socket: Can't assign requested address for
165518.532 error: can't bind socket: Can't assign requested address for
165518.532 error: can't bind socket: Can't assign requested address for
165518.533 error: can't bind socket: Can't assign requested address for
165518.533 error: can't bind socket: Can't assign requested address for
165518.533 error: can't bind socket: Can't assign requested address for
165518.533 error: can't bind socket: Can't assign requested address for
165518.533 error: can't bind socket: Can't assign requested address for
165518.533 error: can't bind socket: Can't assign requested address for
165518.533 error: can't bind socket: Can't assign requested address for
165518.533 error: can't bind socket: Can't assign requested address for
165518.533 error: can't bind socket: Can't assign requested address for
165518.534 error: can't bind socket: Can't assign requested address for
165518.534 error: can't bind socket: Can't assign requested address for
165518.534 error: can't bind socket: Can't assign requested address for
165518.534 error: can't bind socket: Can't assign requested address for
165518.534 error: can't bind socket: Can't assign requested address for
165518.534 error: can't bind socket: Can't assign requested address for
165518.534 error: can't bind socket: Can't assign requested address for
165518.534 error: can't bind socket: Can't assign requested address for
165518.535 error: can't bind socket: Can't assign requested address for
165518.535 error: can't bind socket: Can't assign requested address for
165518.535 error: can't bind socket: Can't assign requested address for
165518.535 error: can't bind socket: Can't assign requested address for
165518.535 error: can't bind socket: Can't assign requested address for
165518.535 error: can't bind socket: Can't assign requested address for
165518.535 error: can't bind socket: Can't assign requested address for
165518.535 error: can't bind socket: Can't assign requested address for
165518.535 error: can't bind socket: Can't assign requested address for
165518.535 error: can't bind socket: Can't assign requested address for
165518.536 error: can't bind socket: Can't assign requested address for
165518.536 error: can't bind socket: Can't assign requested address for
165518.536 error: can't bind socket: Can't assign requested address for
165518.536 error: can't bind socket: Can't assign requested address for
165518.536 error: can't bind socket: Can't assign requested address for
165518.536 error: can't bind socket: Can't assign requested address for
165518.536 error: can't bind socket: Can't assign requested address for
165518.536 error: can't bind socket: Can't assign requested address for
165518.536 error: can't bind socket: Can't assign requested address for

[Mark_Deneen]

I’m guessing that your supervisor process, whether it be systemd, runit, etc, is repeatedly starting unbound. Unbound prints this error message, exits, and then is launched again.

[Mike1]

Unbound is running continuously. I do not see the usual unbound
start-up messages in the logs, just that one log message repeated.

Maybe something within unbound is restarting an unbound process? I
don't know, which is why I'm asking.

I should have added this initially:

Unbound Version 1.6.8, running on OpenBSD 6.3 (amd64)

[Eric_Luehrsen]

The problem is Unbound logs for each outbound connection it cannot make. This is not a restart issue. The solutuon should be in Unbound where this message has a burn down timer. When a message is sent, the time is recorded and messages are not sent until (config) time later. Pretty simple if() gating the syslog call. Default should be 5 minutes as many outages are hour or more.

- Eric

[Eric_Luehrsen]

I may have been ambiguous. I mean a burn down timer on log messages, rather than UPD query messages.
- Eric

[Eric_Luehrsen]

Reduce log noise when an interface goes missing during
reconfiguration. It is a crude patch requiring quality control
but it demonstrates the concept.

Index: services/listen_dnsport.c

[A_Schulze]

Eric Luehrsen via Unbound-users:

Reduce log noise when an interface goes missing during
reconfiguration. It is a crude patch requiring quality control
but it demonstrates the concept.

sorry, I don't really like that concept.

without proposing details: unbound is able to detect a destination as unreachable.
Why doesn't catch this logic Mike's "link down" state?

Andreas

[Wouter]

Hi,

[Wouter]

Hi,

[Mike1]

Thanks for the patch. I'll give it a try.

[Mike1]

For me, the patch results in something along these lines:

#ifdef EADDRINUSE
  *inuse = (errno == EADDRINUSE);
  /* detect freebsd jail with no ipv6 permission */

  if(family==AF_INET6 && errno==EINVAL)
     *noproto = 1;
  else if(errno != EADDRINUSE &&
     !(errno == EACCES && verbosity < 4 && !listen)
#ifdef EADDRNOTAVAIL
     !(errno == EADDRNOTAVAIL && verbosity < 4 && !listen)
#endif
     ) {
    log_err_addr("can't bind socket", strerror(errno),
       (struct sockaddr_storage*)addr, addrlen);
     }

#endif /* EADDRINUSE */

Inside the #ifdef EADDRNOTAVAIL block, should there be a && or a ||
preceding the !(errno ?

[Wouter]

Hi Mike,

Hi,

[snip]

How about this patch, no timers involved. It works based on
verbosity. You either want debug style logs or you don't. There
is already a bunch of code in unbound to stop repeated logs from
error messages from the network system. This stops this
particular one, it was simply not reported before.

Index: services/listen_dnsport.c

--- services/listen_dnsport.c (revision 4930)

+++ services/listen_dnsport.c (working copy) @@ -565,7
+565,11 @@ if(family==AF_INET6 && errno==EINVAL) *noproto = 1;
else if(errno != EADDRINUSE && - !(errno == EACCES &&
verbosity < 4 && !listen)) { + !(errno == EACCES &&
verbosity < 4 && !listen) +#ifdef EADDRNOTAVAIL + !(errno ==
EADDRNOTAVAIL && verbosity < 4 && !listen) +#endif + ) {
log_err_addr("can't bind socket", strerror(errno), (struct
sockaddr_storage*)addr, addrlen); }

For me, the patch results in something along these lines:

#ifdef EADDRINUSE *inuse = (errno == EADDRINUSE); /* detect
freebsd jail with no ipv6 permission */

if(family==AF_INET6 && errno==EINVAL) *noproto = 1; else if(errno
!= EADDRINUSE && !(errno == EACCES && verbosity < 4 && !listen)
#ifdef EADDRNOTAVAIL !(errno == EADDRNOTAVAIL && verbosity < 4 &&
!listen) #endif ) { log_err_addr("can't bind socket",
strerror(errno), (struct sockaddr_storage*)addr, addrlen); }

#endif /* EADDRINUSE */

Inside the #ifdef EADDRNOTAVAIL block, should there be a && or a ||
preceding the !(errno ?

It should be && That is also in the code repository and in a second
fixed patch I emailed after that. Sorry for the typing error there.

Best regards, Wouter

[Mike1]

Hi Mike,

Greets.

[snip]

It should be && That is also in the code repository and in a second
fixed patch I emailed after that. Sorry for the typing error there.

Thanks for the follow-up.

For some reason I missed the second reply with the fixed patch.

But I should have checked the code repository before I sent my reply.

In any case, many thanks for the follow-up.

I'm in the process of setting up a OpenBSD 6.4 current box to do some
testing....

[Mike1]

Hi,

Greets

[snip]

I just wanted to circle back to let you know that I did some quick
testing of the patch on OpenBSD 6.4, which is in pre-release mode at the
moment. It had unbound 1.8.0.

To simulate the ISP outage, I used ifconfig to delete the
"outgoing-interface" IP address from the interface.

Without the patch, as expected, the log file grew rapidly.

With the patch, there was no enthusiastic logging.

Thanks again for the quick turnaround on this.

Mike.