Veamos con un ejemplo la utilidad de la herramienta strace para hacer debug cuando los logs no proporcionan información detallada.

El escenario es el siguiente:

Postfix instalado desde los «Squeeze backports«, con usuarios virtuales en un directorio ldap consultado mediante ldaps (sobre SSL).

Con esta configuración, cuando el servidor smtp recibe un correo e intenta verificar su existencia en el directorio ldap, se produce el siguiente error:

Nov 13 10:05:44 test postfix/master[1908]: warning: process
/usr/lib/postfix/smtpd pid 7863 killed by signal 6

Se aisló el problema «hablando» mediante telnet con el servidor smtp ya que se observó que la traza anterior siempre aparecía en los logs cuando se enviaba el «RCPT TO:«

Si el acceso al directorio es sobre ldap sin SSL, el funcionamiento es correcto.

No obstante, no hay ninguna otra traza en los logs que nos de más información y aquí es cuando strace viene al rescate ;)

Engancharemos strace al proceso de postfix en ejecución con la opción -p «pid«.

Para que no corte mensajes, especificamos un mayor tamaño de string con la opción «-s«.

Una opción fundamental es la de «follow forks (-f)» para hacer debug de los procesos hijos creados, ya que se crea un nuevo proceso smtpd hijo del proceso «master» al conectar al servidor.

Con la opción «-tt» especificamos que nos añada una marca de tiempo en microsegundos a cada salida que nos vendrá bien para saber cuándo están ocurriendo las cosas.

Finalmente, puesto que nos proporcionará muchísima información filtraremos la salida especificando que sólo nos muestre información relativa a llamadas al sistema que se refieren a ficheros (-e trace=file).

El comando completo quedaría:

strace -tt -s 4096 -f -p 8269 -e trace=file

En la salida generada encontramos una línea muy significativa:

...
[pid  8685] 11:22:48.720192 access("/dev/random", R_OK) = -1 ENOENT
(No such file or directory)
...

La instalación por defecto ejecuta postfix enjaulado y efectivamente comprobamos que /dev/random no se crea por defecto en el «chroot» de postfix.

[root@desdelaconsola.es]# ls /var/spool/postfix/dev/random
ls: no se puede acceder a /var/spool/postfix/dev/rindom: No existe el fichero o el directorio

Tiene mucho sentido que el error sólo ocurra cuando la conexión al directorio ldap se realiza sobre SSL ya que /dev/random es usado para generar la entropía necesaria para la conexión SSL.

Podemos crearlo manualmente con los comandos:

root@desdelaconsola.es:/var/spool/postfix/dev# mknod random c 1 8
root@desdelaconsola.es:/var/spool/postfix/dev# chmod 666 random

Ahora el envío a destinatarios contenidos en el directorio ldap (y consultados por LDAPS) se realiza sin problemas :)

He reproducido el problema en un sistema limpio instalando postfix desde los backports en Debian Squeeze por lo que me decidí a reportar un bug a los mantenedores de Postfix en Debian.

Para reportar un bug a Debian hay unas instrucciones perfectamente detalladas, pero básicamente se puede hacer usando la herramienta «reportbug» o mandando un correo con una estructura determinada.

Este es el reporte del bug al que hace referencia este post.