Chapter 10. Advanced Issues

Table of Contents
10.1 Debugging Postfix
10.2 The chroot jail
10.3 Anti-UCE

In this section we're going to cover some debugging, discuss the chroot jail and talk about UCE.

10.1 Debugging Postfix

You've probably noticed some odd stuff at the end of the last couple of these configs. Here's what I mean:

   #debugger_command = /usr/bin/strace -p $process_id -o /tmp/smtpd.$process_id & sleep 5
   

What this does is (if it's enabled in the master.cf) allow you to log a trace of actual e-mail deliveries. It can be really beneficial if you're having troubles. Here is the line you need in you master.cf to make this work:

   #smtp unix - - y - - smtp -D
   

If you uncommented this line you'd have an instant debugger which will log what's happening by reading the system calls during the smtpd process. Once this is done cd into /tmp and you'll find a file which has the name smtpd.xxxxx where xxxxx = the pid of the process that created the file. Here is a sample:

   wait4(29612, [WIFEXITED(s) && WEXITSTATUS(s) == 0], 0, NULL) = 29612
   SYS_174(0x2, 0xbffff844, 0, 0x8, 0x2)   = 0
   SYS_174(0x3, 0xbffff838, 0, 0x8, 0x3)   = 0
   SYS_175(0x2, 0xbffff930, 0, 0x8, 0x2)   = 0
   --- SIGCHLD (Child exited) ---
   open("pid/unix.smtp", O_RDWR)           = 6
   fstat(6, {st_mode=030011, st_size=0, ...}) = 0
   lstat("pid/unix.smtp", {st_mode=030011, st_size=0, ...}) = 0
   fcntl(6, F_GETFD)                       = 0
   fcntl(6, F_SETFD, FD_CLOEXEC)           = 0
   chdir("/var/spool/postfix")             = 0
   open("/etc/postfix/localdomains", O_RDONLY) = 7
   read(7, "company.com\othercompany.com\nl"..., 4096) = 158
   read(7, "", 4096)                       = 0
   close(7)                                = 0
   open("/etc/passwd", O_RDONLY)           = 7
   fcntl(7, F_GETFD)                       = 0
   fcntl(7, F_SETFD, FD_CLOEXEC)           = 0
   fstat(7, {st_mode=S_IFCHR|S_ISUID|S_ISVTX|0477, st_rdev=makedev(120, 35), ...}) = 0
   mmap(0, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40014000
   read(7, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 1886
   close(7)                                = 0
   munmap(0x40014000, 4096)                = 0
   setgid(12345)                           = 0
   open("/etc/group", O_RDONLY)            = 7
   fcntl(7, F_GETFD)                       = 0
   fcntl(7, F_SETFD, FD_CLOEXEC)           = 0
   fstat(7, {st_mode=S_IFCHR|S_ISUID|S_ISVTX|0507, st_rdev=makedev(120, 37), ...}) = 0
   mmap(0, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40014000
   _llseek(0x7, 0, 0, 0xbffff9b0, 0x1)     = 0
   read(7, "root::0:root\nbin::1:root,bin,da"..., 4096) = 833
   read(7, "", 4096)                       = 0
   close(7)                                = 0
   munmap(0x40014000, 4096)                = 0
   open("/etc/ld.so.cache", O_RDONLY)      = 7
   fstat(7, {st_mode=0, st_size=0, ...})   = 0
   mmap(0, 21705, PROT_READ, MAP_PRIVATE, 7, 0) = 0x40014000
   close(7)                                = 0
   open("/lib/libnss_nisplus.so.2", O_RDONLY) = 7
   fstat(7, {st_mode=0, st_size=0, ...})   = 0
   read(7, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3"..., 4096) = 4096
   mmap(0, 40884, PROT_READ|PROT_EXEC, MAP_PRIVATE, 7, 0) = 0x40170000
   mprotect(0x40179000, 4020, PROT_NONE)   = 0
   mmap(0x40179000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 7, 0x8000) = 0x40179000
   close(7)                                = 0
   munmap(0x40014000, 21705)               = 0
   uname({sys="Linux", node="server.company.com", ...}) = 0
   open("/var/nis/NIS_COLD_START", O_RDONLY) = -1 ENOENT (No such file or directory)
   open("/etc/ld.so.cache", O_RDONLY)      = 7
   fstat(7, {st_mode=0, st_size=0, ...})   = 0
   mmap(0, 21705, PROT_READ, MAP_PRIVATE, 7, 0) = 0x40014000
   close(7)                                = 0
   open("/lib/libnss_nis.so.2", O_RDONLY)  = 7
   fstat(7, {st_mode=0, st_size=0, ...})   = 0
   read(7, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3"..., 4096) = 4096
   mmap(0, 36368, PROT_READ|PROT_EXEC, MAP_PRIVATE, 7, 0) = 0x4017a000
   mprotect(0x40182000, 3600, PROT_NONE)   = 0
   close(7)                                = 0
   munmap(0x40014000, 21705)               = 0
   uname({sys="Linux", node="server.company.com", ...}) = 0
   setgroups(1, [12345])                   = 0
   chroot("/var/spool/postfix")            = 0
   chdir("/")                              = 0
   setuid(12345)                           = 0
   getrlimit(RLIMIT_NOFILE, {rlim_cur=1024, rlim_max=1024}) = 0
   setrlimit(RLIMIT_NOFILE, {rlim_cur=1024, rlim_max=1024}) = 0
   brk(0x8069000)                          = 0x8069000
   time([942569512])                       = 942569512
   time([942569512])                       = 942569512
   fcntl(4, F_GETFD)                       = 0
   fcntl(4, F_SETFD, FD_CLOEXEC)           = 0
   fcntl(3, F_GETFD)                       = 0
   fcntl(3, F_SETFD, FD_CLOEXEC)           = 0
   alarm(0)                                = 0
   SYS_174(0xe, 0xbffffa6c, 0xbffff9e0, 0x8, 0xe) = 0
   alarm(0)                                = 0
   flock(6, LOCK_EX)                       = 0
   alarm(6000)                             = 0
   time(NULL)                              = 942569512
   select(5, [3 4], [], [3 4], {100, 0})   = 1 (in [4], left {100, 0})
   time(NULL)                              = 942569512
   accept(4, 0, NULL)                      = 7
   flock(6, LOCK_UN)                       = 0
   fcntl(7, F_GETFL)                       = 0x2 (flags O_RDWR)
   fcntl(7, F_SETFL, O_RDWR)               = 0
   fcntl(7, F_GETFD)                       = 0
   fcntl(7, F_SETFD, FD_CLOEXEC)           = 0
   write(3, "\253s\0\0\0\0\0\0", 8)        = 8
   select(8, NULL, [7], [7], {3600, 0})    = 1 (out [7], left {3600, 0})
   write(7, "0\0", 2)                      = 2
   select(8, [7], NULL, [7], NULL)         = 1 (in [7])
   ioctl(7, FIONREAD, [112])               = 0
   select(8, [7], NULL, [7], {3600, 0})    = 1 (in [7], left {3600, 0})
   read(7, "active\000541B31A803\00085\00025"..., 4096) = 112
   lstat("active/541B31A803", {st_mode=S_ISVTX|0170, st_size=0, ...}) = 0
   open("active/541B31A803", O_RDWR)       = 8
   flock(8, LOCK_SH|LOCK_NB)               = 0
   fcntl(8, F_GETFD)                       = 0
   fcntl(8, F_SETFD, FD_CLOEXEC)           = 0
   open("/etc/ld.so.cache", O_RDONLY)      = -1 ENOENT (No such file or directory)
   open("/lib/i686/mmx/libnss_dns.so.2", O_RDONLY) = -1 ENOENT (No such file or directory)
   stat("/lib/i686/mmx", 0xbffff528)       = -1 ENOENT (No such file or directory)
   open("/lib/i686/libnss_dns.so.2", O_RDONLY) = -1 ENOENT (No such file or directory)
   stat("/lib/i686", 0xbffff528)           = -1 ENOENT (No such file or directory)
   open("/lib/mmx/libnss_dns.so.2", O_RDONLY) = -1 ENOENT (No such file or directory)
   stat("/lib/mmx", 0xbffff528)            = -1 ENOENT (No such file or directory)
   open("/lib/libnss_dns.so.2", O_RDONLY)  = 9
   fstat(9, {st_mode=033405, st_size=0, ...}) = 0
   read(9, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3"..., 4096) = 4096
   mmap(0, 14320, PROT_READ|PROT_EXEC, MAP_PRIVATE, 9, 0) = 0x40014000
   mprotect(0x40017000, 2032, PROT_NONE)   = 0
   mmap(0x40017000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 9, 0x2000) = 0x40017000
   close(9)                                = 0
   open("/var/nis/NIS_COLD_START", O_RDONLY) = -1 ENOENT (No such file or directory)
   open("/var/nis/NIS_COLD_START", O_RDONLY) = -1 ENOENT (No such file or directory)
   open("/etc/services", O_RDONLY)         = 9
   fcntl(9, F_GETFD)                       = 0
   fcntl(9, F_SETFD, FD_CLOEXEC)           = 0
   fstat(9, {st_mode=S_IFCHR|S_ISUID|S_ISVTX|0423, st_rdev=makedev(113, 92), ...}) = 0
   mmap(0, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40018000
   read(9, "# /etc/services:\n# $Id: service"..., 4096) = 4096
   close(9)                                = 0
   munmap(0x40018000, 4096)                = 0
   socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 9
   socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 10
   ioctl(10, SIOCGIFCONF, 0xbffff920)      = 0
   close(10)                               = 0
   connect(9, {sin_family=AF_INET, sin_port=htons(25), sin_addr=inet_addr("12.4.13.46")}, 16) = 0
   select(10, [9], NULL, [9], {300, 0})    = 1 (in [9], left {299, 760000})
   brk(0x806b000)                          = 0x806b000
   read(9, "220 ns.company.org ESMTP Postf"..., 4096) = 60
   select(10, NULL, [9], [9], {300, 0})    = 1 (out [9], left {300, 0})
   write(9, "EHLO server.company.com\r\n", 27) = 27
   select(10, [9], NULL, [9], {300, 0})    = 1 (in [9], left {299, 870000})
   read(9, "250-ns.company.org\r\n250-PIPE"..., 4096) = 81
   getsockopt(9, SOL_SOCKET, SO_SNDBUF, [65535], [4]) = 0
   gettimeofday({942569513, 112371}, NULL) = 0
   getpid()                                = 29611
   open("/etc/resolv.conf", O_RDONLY)      = 10
   fstat(10, {st_mode=S_ISGID|S_ISVTX|0406, st_size=0, ...}) = 0
   mmap(0, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40018000
   read(10, "search company.com\nnameserver"..., 4096) = 96
   read(10, "", 4096)                      = 0
   close(10)                               = 0
   munmap(0x40018000, 4096)                = 0
   socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 10
   connect(10, {sin_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("216.228.97.50")}, 16) = 0
   send(10, "\275r\1\0\0\1\0\0\0\0\0\0\tcompa"..., 31, 0) = 31
   SYS_168(0xbfffd584, 0x1, 0x1388, 0x1388, 0xbfffd584) = 1
   recvfrom(10, "\275r\205\200\0\1\0\2\0\4\0\5\tm"..., 4096, 0, {sin_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("200.200.7.50")}, [16]) = 253
   close(10)                               = 0
   socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 10
   connect(10, {sin_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("200.200.7.50")}, 16) = 0
   send(10, "\275s\1\0\0\1\0\0\0\0\0\0\3[12\001"..., 30, 0) = 30
   SYS_168(0xbfffd584, 0x1, 0x1388, 0x1388, 0xbfffd584) = 1
   recvfrom(10, "\275s\205\203\0\1\0\0\0\1\0\0\3["..., 4096, 0, {sin_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("216.228.97.50")}, [16]) = 103
   close(10)                               = 0
   socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 10
   connect(10, {sin_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("216.228.97.50")}, 16) = 0
   send(10, "\275t\1\0\0\1\0\0\0\0\0\0\3[12\001"..., 30, 0) = 30
   SYS_168(0xbfffd584, 0x1, 0x1388, 0x1388, 0xbfffd584) = 1
   recvfrom(10, "\275t\201\203\0\1\0\0\0\1\0\0\3["..., 4096, 0, {sin_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("200.200.7.50")}, [16]) = 103
   close(10)                               = 0
   select(10, NULL, [9], [9], {300, 0})    = 1 (out [9], left {300, 0})
   write(9, "MAIL FROM:<root@company.com> S"..., 78) = 78
   select(10, [9], NULL, [9], {300, 0})    = 1 (in [9], left {298, 790000})
   read(9, "250 Ok\r\n250 Ok\r\n354 End data"..., 4096) = 53
   lseek(8, 85, SEEK_SET)                  = 85
   brk(0x806d000)                          = 0x806d000
   read(8, "N:Received: by server.company."..., 4096) = 2532
   select(10, NULL, [9], [9], {600, 0})    = 1 (out [9], left {600, 0})
   write(9, "Received: by server.company.co"..., 2513) = 2513
   select(10, [9], NULL, [9], {600, 0})    = 1 (in [9], left {599, 340000})
   read(9, "250 Ok: queued as 99EE4191C\r\n2"..., 4096) = 38
   time(NULL)                              = 942569515
   brk(0x8070000)                          = 0x8070000
   time([942569515])                       = 942569515
   getpid()                                = 29611
   SYS_174(0xd, 0xbffff5fc, 0xbffff570, 0x8, 0xd) = 0
   send(5, "<22>Nov 11 03:51:55 postfix/smtp"..., 159, 0) = 159
   SYS_174(0xd, 0xbffff600, 0, 0x8, 0xd)   = 0
   lseek(8, 48, SEEK_SET)                  = 48
   write(8, "D", 1)                        = 1
   close(9)                                = 0
   select(8, NULL, [7], [7], {3600, 0})    = 1 (out [7], left {3600, 0})
   write(7, "\0000\0", 3)                  = 3
   select(8, [7], NULL, [7], {3600, 0})    = 1 (in [7], left {3600, 0})
   read(7, "", 4096)                       = 0
   close(8)                                = 0
   close(7)                                = 0
   write(3, "\253s\0\0\1\0\0\0", 8)        = 8
   time([942569515])                       = 942569515
   alarm(0)                                = 5998
   flock(6, LOCK_EX)                       = 0
   alarm(6000)                             = 0
   time(NULL)                              = 942569515
   select(5, [3 4], [], [3 4], {100, 0})   = 1 (in [3], left {66, 20000})
   time(NULL)                              = 942569549
   _exit(0)                                = ?
   

If you were having nameserver troubles this would be an excellent way to find out what was going on. Note that the same type of test could be done with ltrace if you were actually having problems with Postfix binaries. Either type of test may be accomplished for any of the Postfix binaries by putting a “-D” after its entry in the master.cf file.