mar 04 agosto 2015
Por Javier Cantero
En Linux .
etiq.: bind9 logs
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