Desde que escribí "Logs, bind9 e IPv6" tenía pendiente echar un vistazo al resto de mensajes que bind9 estaba generando en los logs del sistema. Además de un montón de ruido inútil, el problema es que a través de estos mensajes se filtra cierta cantidad de información privada sobre los sitios que visitamos/accedemos (¡Hola NSA!), tanto consciente como inconscientemente¹.

Mi proposito es por un lado reducir los mensajes que se están registrando en los logs, dejando únicamente aquellos que realmente merece la pena registrar, y por otro gestionar los logs de bind9 de forma separada de los del resto del sistema para poder establecer políticas de expiración diferentes. Afortunadamente bind9 tiene su propio sistema de logging interno, por lo que no tendremos que recurrir a jugar con la configuración de los logs del sistema.

Logging en bind9

La documentación oficial de bind9 describe la sintaxis para configurar el sistema de logging. Este sistema se basa en dos conceptos: los canales y las categorías. Los canales definen dónde se mandarán los mensajes de log: a un fichero, al syslog, a la salida estándar de error o a ningún sitio —null—. Además se pueden definir algunos detalles adicionales, como el nivel de gravedad (severity) mínimo de los mensajes, así como algunas opciones sobre campos a incluir en cada mensaje de log —como un timestamp o la propia severity—.

Las categorías por su parte sirven para agrupar los mensajes de bind9 que tienen similar causa o subsistema de origen. Por ejemplo tenemos categorías como queries, network, database, security, etc (para una lista completa consultad la documentación). El sistema de logging de bind9 permite definir qué categorías de mensajes se van a mandar a qué canales. Cada categoría puede mandarse a varios canales, y de hecho la configuración por defecto (que es la que se usa si no se indica nada) utiliza esto para mandar los mensajes de log tanto a los logs del sistema como a un canal especial de debug. Es lo mismo que si se hubiera escrito:

logging {
     category default { default_syslog; default_debug; };
     category unmatched { null; };
};

La categoría default es la "recoge-todo": toda categoría para la que no se definan canales usa los definidos en ésta. La categoría unmatched es también especial y sólo sirve para recoger los mensajes que por la razón que sea no tienen categoría. Como se puede observar, estos mensajes sin categoría se ignoran (se mandan al canal null). Los mensajes con categoría, como no hay definida ninguna otra categoría aparte de default, acaban todos enviándose a los canales por defecto default_syslog y default_debug. Estos dos canales están definidos por defecto así:

channel default_syslog {
    syslog daemon;
    severity info;
};

channel default_debug {
    file "named.run";
    severity dynamic;
};

El primer canal simplemente manda los mensajes de bind9 de gravedad info o mayor al syslog —rsyslog, journald o el que sea—. En el caso de rsyslog los mensajes acabarán normalmente en el fichero /var/log/syslog. El segundo canal es como he dicho especial, y sirve para hacer debugging de bind9. El nivel de la gravedad de los mensajes de este canal es variable (dynamic) y depende del valor (un número entre 1 y 99) pasado a named mediante la opcion -d de la línea de comandos cuando se lanzó el proceso. Este valor también se puede cambiar durante ejecución mediante los comando rndc trace <valor> y rndc notrace. El canal default_debug normalmente manda los mensajes de log a un fichero, pero si se le ha indicado la opción -f a named en la línea de comandos se usará en su lugar la salida de error estandar. Como systemd por defecto manda la stdout y la stderr de los demonios que arranca al syslog, y rsyslog almacena los mensajes daemon.* en /var/log/daemon.log, los mensajes de bind9 terminan apareciendo por duplicado en ambos ficheros de log.

Mi configuración va a ser diferente: no voy a mandar nada al syslog, sino que guardaré todo en ficheros controlados directamente por named. Lo primero de todo es crear el fichero de configuración de bind9 dónde escribiré la configuración de logging. He decidido ponerla en un fichero llamado /etc/bind/named.conf.logging separado del resto de los ficheros de configuración para que las actualizaciones de paquetes no me la pisen. Para que named lea este fichero hay que incluirlo desde /etc/named.conf:

include "/etc/bind/named.conf.logging";
include "/etc/bind/named.conf.options";
include "/etc/bind/named.conf.local";
include "/etc/bind/named.conf.default-zones";

Ahora pasemos a rellenar /etc/bind/named.conf.logging. Lo primero que voy a hacer es definir mi propio canal al que llamaré file_log:

logging {
    channel file_log {
        file "/var/log/bind9/named.log" versions 2 size 50k;
        severity info;
        print-time yes;
        print-severity yes;
        print-category yes;
    };
    category default { file_log; default_debug; };
    category unmatched { null; };
};

Este canal manda los mensajes de log a un fichero llamado /var/log/bind9/named.log. Es necesario crear dicho fichero de antemano, y su propietario y grupo deben ser bind:bind. La severity del nuevo canal es la misma que había por defecto (info) y además le he indicado que añada a cada mensaje de log la fecha/hora en que se produjo, la gravedad del mismo y la categoría a la que pertenece. En el caso de syslog la fecha/hora es redundante, pero aquí si no la activamos no sabremos cuando ocurrió cada mensaje. Los otros dos campos simplemente me ayudarán en mi investigación.

No es necesario incluir este nuevo fichero en las políticas de logrotate, ya que el propio bind9 permite declarar la política de rotación de logs del fichero de un canal. La palabra clave versions nos permite indicar cuántas rotaciones (ficheros) queremos tener como máximo, y si añadimos size se limitará el tamaño máximo que alcanzará el fichero de log antes de rotar (si no se rotará cada vez que se arranque o recargue named).

Pero hay un pequeño problema: named va a tratar de crear los distintos ficheros de rotación en el mismo directorio que el fichero de log, y normalmente lo hace ejecutándose como usuario bind. Si el directorio del fichero de log no permite escribir ficheros al usuario bind (como es el caso de /var/log que es propiedad de root), esto va a provocar errores de permisos cada vez que se intenten rotar los logs. Es por esta razón por la que arriba he puesto el fichero de log dentro de un subdirectorio /var/log/bind9/ cuyo propietario es bind:bind y en el que named pueda guardar y rotar los ficheros sin problemas.

Como mi objetivo es limitar la cantidad de información que pueda filtrarse a través de este fichero, he puesto una política muy agresiva de "olvido" (sólo dos ficheros de log de 50 KB cada uno como máximo). En teoría no debería ser mayor problema, ya que, una vez bien configuradas las categorías de mensajes, el número de líneas del fichero debería ser mínimo.

Errores y categorías

A continuación pondré una lista de distintos mensajes de log que he encontrado durante un pequeño periodo de pruebas. He ocultado los datos de dominios e IPs (se dice el pecado pero no el pecador. ;-)) y he incluido los campos de categoría y severity para el posterior análisis:

resolver: notice: DNS format error from XX.XX.XX.XX#53 resolving www.ejemplo.dom/AAAA for client 127.0.0.1#33333: Name ejemplo.dom (SOA) not subdomain of zone www.ejemplo.dom -- invalid response
lame-servers: info: error (FORMERR) resolving 'www.ejemplo.dom/AAAA/IN': XX.XX.XX.XX#53

lame-servers: info: error (unexpected RCODE REFUSED) resolving 'www.ejemplo.dom/AAAA/IN': XX.XX.XX.XX#53
lame-servers: info: error (unexpected RCODE SERVFAIL) resolving 'www.ejemplo.dom/A/IN': XX.XX.XX.XX#53
lame-servers: info: error (connection refused) resolving 'www.ejemplo.dom/A/IN': XX.XX.XX.XX#53
lame-servers: info: lame server resolving 'www.ejemplo.dom' (in 'ejemplo.dom'?): XX.XX.XX.XX#53

edns-disabled: info: success resolving 'www.ejemplo.dom/A' (in 'ejemplo.dom'?) after reducing the advertised EDNS UDP packet size to 512 octets
edns-disabled: info: success resolving 'www.ejemplo.dom/A' (in 'www.ejemplo.dom'?) after disabling EDNS

dnssec: info: validating @0x7fxxxxxxxxxx: www.ejemplo.dom A: no valid signature found
dnssec: info: validating @0x7fxxxxxxxxxx: www.ejemplo.dom AAAA: no valid signature found
dnssec: info:   validating @0x7fxxxxxxxxxx: ejemplo.dom SOA: no valid signature found
dnssec: info:   validating @0x7fxxxxxxxxxx: www.ejemplo.dom NSEC: no valid signature found

Estos son los mensajes más repetidos, especialmente los dos primeros que vienen en pareja. También he encontrado otros mucho menos frecuentes:

resolver: notice: DNS format error from XX.XX.XX.XX#53 resolving www.ejemplo.dom/AAAA for client 127.0.0.1#44444: non-improving referral
lame-servers: info: error (insecurity proof failed) resolving 'ejemplo.dom/DNSKEY/IN': XX.XX.XX.XX#53
lame-servers: info: error (no valid DS) resolving 'www.ejemplo.dom/A/IN': XX.XX.XX.XX#53
lame-servers: info: error (no valid RRSIG) resolving 'ejemplo.dom/DS/IN': XX.XX.XX.XX#53
dnssec: info: validating @0x7fxxxxxxxxxx: ejemplo.dom DNSKEY: got insecure response; parent indicates it should be secure

La severity de todos estos mensajes es info salvo para los dos mensajes de la categoría resolver que son notice, así que se podría simplemente indicar un severity warning; en el canal para descartar todos estos mensajes. Pero, y es aquí es cuando podemos empezar a intuir los inconvenientes del diseño del sistema de logging de bind9, así descartaríamos también cualquier otro mensaje de gravedad info o notice. Es por esa causa por la que se implementan las categorías, ya que éstas permiten una forma más específica de tratar los distintos mensajes.

Las categorías a las que pertenecen estos mensajes son: lame-servers, resolver, dnssec y edns-disabled. De ellas, lame-servers es la primera candidata a descartar, ya que es una categoría que reune precisamente el tipo de mensajes que genera bind9 cuando se encuentra con que otro servidor no está comportándose como debiera, e informa de ello. Como en estos casos es siempre el otro servidor está mal configurado, y raramente podemos hacer algo al respecto, estos mensajes son de los que no merece la pena informar al administrador y por lo tanto ignoraremos la categoría entera mandándola al canal null. Esta es una configuración muy común, pero por alguna razón —al menos en Debian— no viene por defecto.

Las otras 3 categorías en principio me van a requerir una investigación más profunda. He encontrado este bug #584557 en el BTS de Debian en el que que se solicita descartar las categorías resolver y edns-disabled:

Please suppress the "resolver" log category, on the grounds that it spams the system log a great deal, and just like "edns-disabled" and "lame-servers", refers to issues completely outside of the hability of the local nameserver operator to fix, AND extremely unlikely to get fixed even if reported.

[...]

Sideway referals are very common practice in the ARIN region, most people either don't care, or don't even understand that they introduce undue latency. Even clueful admins like the kernel.org people use them. I bet we have some of that in debian.org/debian.net as well.

As for the invalid response, a very common cause for that are broken load-balancer setups. Just like the ECN IP functionality, tracking this is a lost cause that will fix itself in a couple decades and will resist any efforts to accelerate the process (unless, say, someone from the top tier like Google decides to use a massive large hammer and face lawsuits over it).

No es la única referencia que he encontrado que atribuye esos mensajes de resolver y sus FORMERR asociados a problemas con load balancers mal configurados. De todas formas el bug (fusionado con el ##492901) sigue 6 años despues abierto, aunque puede deberse simplemente a que el mantenimiento del paquete bind9 en Debian parece centrado exclusivamente en cerrar agujeros de seguridad.

Los mensajes de edns-disabled por su parte parece que se deben a firewalls mal configurados que filtran los paquetes EDNS de más de 512 bytes. Los mensajes se pueden eliminar también de otra forma: reduciendo el tamaño de los paquetes EDNS recibidos a 512 bytes mediante la opción² edns-udp-size 512;. Pero esta opción anula la razón de ser de la extensión EDNS (que es emplear paquetes UDP de hasta 4096 bytes) y haría que la resolución en general fuera más lenta. El manual de bind9 dice acerca de esta opción:

edns-udp-size

Sets the advertised EDNS UDP buffer size in bytes to control the size of packets received. Valid values are 512 to 4096 (values outside this range will be silently adjusted). The default value is 4096. The usual reason for setting edns-udp-size to a non-default value is to get UDP answers to pass through broken firewalls that block fragmented packets and/or block UDP packets that are greater than 512 bytes.

named will fallback to using 512 bytes if it get a series of timeout at the initial value. 512 bytes is not being offered to encourage sites to fix their firewalls. Small EDNS UDP sizes will result in the excessive use of TCP.

Creo que la decisión más inteligente en este caso es seguir usando EDNS con 4096 bytes, que es más óptimo, e ignorar los mensajes provenientes de servidores DNS tras firewalls mal configurados, que son —espero— una minoría.

La última categoría problemática es la de dnssec, que son los mensajes debidos al uso de las extensiones de seguridad de DNS DNSSEC. Este es un tema complejo y no parece que haya mucha gente que controle del mismo, así que parte de las respuestas que he encontrado consisten directamente en desactivar la validación DNSSEC. Del resto, la respuesta más repetida es la de usar la opción dnssec-validation auto; en vez de dnssec-validation yes;, pero resulta que, en el caso de Debian, esta opción ya viene en el fichero de opciones². A partir de ahí, lo máximo que he conseguido averiguar es que los mensajes got insecure response; parent indicates it should be secure indica posiblemente una configuracion incorrecta del DNSSEC del servidor interrogado, y que el caso de los no valid signature found podría (y aquí las cosas no están muy claras) ser también por culpa de la fragmentación de paquetes UDP al pasar por firewalls "problemáticos".

Al final, lo que he decidido es ignorar también todos estos mensajes de categoría dnssec ya que estamos en la misma situación que con los lame-servers y demás: son mensajes sobre problemas que están más allá de nuestro control. Pero no me hace mucha gracia perder los mensajes de esta categoría con severity alta (errores serios de validación). Para esto necesito otro canal con una severity diferente, pero como dudo que bind9 permita a dos canales compartir el mismo fichero de log, necesito un destino distinto para el canal. No quiero usar otro fichero y tener que rotarlo, etc, así que al final, aunque había dicho de no utilizar el syslog, me he definido mi propio canal errors_syslog para recoger los mensajes graves (de severity warning o mayor) en él. El sistema de logging de bind9 no es tan flexible como pudiera parecer a primera vista, y en casos como éste queda en evidencia.

Podría hacer lo mismo con las otras tres categorías, pero he comprobado en el código fuente de bind9 (concretamente el de la versión 9.9.5 que uso) que los mensajes de categorias lame-servers y edns-disabled son todos de gravedad info y los de resolver son mayoritariamente notice o debug (hay alguna excepción que es warning). Por ello esas categorías las voy a ignorar totalmente³, y la versión final de mi named.conf.logging queda por lo tanto así:

logging {
    channel file_log {
            file "/var/log/bind9/named.log" versions 2 size 50k;
            severity info;
            print-time yes;
            print-severity yes;
            print-category yes;
        };
        channel errors_syslog {
            syslog daemon;
            severity warning;
        };
        category lame-servers { null; };
        category edns-disabled { null; };
        category resolver { null; };
        category dnssec { errors_syslog; };
        category default { file_log; errors_syslog; default_debug; };
        category unmatched { null; };
};

No obstante, lo vigilaré durante una temporada por si hay que hacer ajustes a posteriori.

:wq