I finally got around to upgrading my home system from 0.37 to 0.80. As
usual, the upgrade went pretty smoothly. However, I'm seeing a problem
with very slow injections via tmda-sendmail. (One difference is that
0.37 injected locally, 0.80 injects via SMTP.)
I configured mutt to run a tmda-sendmail wrapper that runs it under
strace. It looks like the delays are DNS timeouts, but I can't figure
out why it'd be doing so many lookups or why they'd time out. The
system is attached to a 3com LAN modem that provides DNS service for
the local "sill" domain, as well as caching DNS service for external
hosts.
I've tried setting SMTPHOST to localhost, 127.0.0.1, sparge (the name
of the host)...to no avail. Connecting directly to port 25 via:
telnet localhost 25
is nearly instantaneous.
Here's the abridged strace output:
13:00:15 execve("/usr/local/tmda/bin/tmda-sendmail",
["/usr/local/tmda/bin/tmda-sendmail"], [/* 26 vars */]) = 0
13:00:15 uname({sys="Linux", node="sparge", ...}) = 0
.
.
.
13:00:16 open("/etc/host.conf", O_RDONLY) = 3
13:00:16 fstat64(3, {st_mode=S_IFREG|0644, st_size=17, ...}) = 0
13:00:16 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
0x4009b000
13:00:16 read(3, "order hosts,bind\n", 4096) = 17
13:00:16 read(3, "", 4096) = 0
13:00:16 close(3) = 0
13:00:16 munmap(0x4009b000, 4096) = 0
13:00:16 open("/etc/hosts", O_RDONLY) = 3
13:00:16 fcntl64(3, F_GETFD) = 0
13:00:16 fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
13:00:16 fstat64(3, {st_mode=S_IFREG|0644, st_size=95, ...}) = 0
13:00:16 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
0x4009b000
13:00:16 read(3, "127.0.0.1\tlocalhost.localdomain\t"..., 4096) = 95
13:00:16 read(3, "", 4096) = 0
13:00:16 close(3) = 0
13:00:16 munmap(0x4009b000, 4096) = 0
13:00:16 open("/etc/ld.so.cache", O_RDONLY) = 3
13:00:16 fstat64(3, {st_mode=S_IFREG|0644, st_size=84818, ...}) = 0
13:00:16 old_mmap(NULL, 84818, PROT_READ, MAP_PRIVATE, 3, 0) = 0x4018d000
13:00:16 close(3) = 0
13:00:16 open("/lib/libnss_dns.so.2", O_RDONLY) = 3
13:00:16 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0P\16\0\000"..., 1024)
= 1024
13:00:16 fstat64(3, {st_mode=S_IFREG|0755, st_size=16477, ...}) = 0
13:00:16 old_mmap(NULL, 16272, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0x401ac000
13:00:16 mprotect(0x401af000, 3984, PROT_NONE) = 0
13:00:16 old_mmap(0x401af000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3,
0x2000) = 0x401af000
13:00:16 close(3) = 0
13:00:16 open("/lib/libresolv.so.2", O_RDONLY) = 3
13:00:16 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\20\'\0"..., 1024) =
1024
13:00:16 fstat64(3, {st_mode=S_IFREG|0755, st_size=68925, ...}) = 0
13:00:16 old_mmap(NULL, 69408, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0x401b0000
13:00:16 mprotect(0x401be000, 12064, PROT_NONE) = 0
13:00:16 old_mmap(0x401be000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3,
0xe000) = 0x401be000
13:00:16 old_mmap(0x401bf000, 7968, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x401bf000
13:00:16 close(3) = 0
13:00:16 munmap(0x4018d000, 84818) = 0
13:00:16 brk(0x826e000) = 0x826e000
13:00:16 brk(0x827f000) = 0x827f000
13:00:16 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 3
13:00:16 connect(3, {sin_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("192.168.1.1")}}, 28) = 0
13:00:16 send(3, "\276\311\1\0\0\1\0\0\0\0\0\0\6sparge\4sill\0\0\34\0\1", 29, 0) = 29
13:00:16 gettimeofday({1058374816, 758919}, NULL) = 0
13:00:16 poll([{fd=3, events=POLLIN}], 1, 5000) = 0
13:00:21 send(3, "\276\311\1\0\0\1\0\0\0\0\0\0\6sparge\4sill\0\0\34\0\1", 29, 0) = 29
13:00:21 gettimeofday({1058374821, 761879}, NULL) = 0
13:00:21 poll([{fd=3, events=POLLIN}], 1, 5000) = 0
13:00:26 close(3) = 0
13:00:26 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 3
13:00:26 connect(3, {sin_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("192.168.1.1")}}, 28) = 0
13:00:26 send(3, "\276\312\1\0\0\1\0\0\0\0\0\0\6sparge\0\0\34\0\1", 24, 0) = 24
13:00:26 gettimeofday({1058374826, 772493}, NULL) = 0
13:00:26 poll([{fd=3, events=POLLIN}], 1, 5000) = 0
13:00:31 send(3, "\276\312\1\0\0\1\0\0\0\0\0\0\6sparge\0\0\34\0\1", 24, 0) = 24
13:00:31 gettimeofday({1058374831, 781938}, NULL) = 0
13:00:31 poll([{fd=3, events=POLLIN}], 1, 5000) = 0
13:00:36 close(3) = 0
13:00:36 brk(0x825d000) = 0x825d000
13:00:36 gettimeofday({1058374836, 792272}, NULL) = 0
13:00:36 getpid() = 23980
13:00:36 open("/etc/resolv.conf", O_RDONLY) = 3
13:00:36 fstat64(3, {st_mode=S_IFREG|0644, st_size=36, ...}) = 0
13:00:36 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
0x4009b000
13:00:36 read(3, "search sill \nnameserver 192.168."..., 4096) = 36
13:00:36 read(3, "", 4096) = 0
13:00:36 close(3) = 0
13:00:36 munmap(0x4009b000, 4096) = 0
13:00:36 socket(PF_UNIX, SOCK_STREAM, 0) = 3
13:00:36 connect(3, {sin_family=AF_UNIX, path="/var/run/.nscd_socket"}, 110) = -1
ENOENT (No such file or directory)
13:00:36 close(3) = 0
13:00:36 open("/etc/hosts", O_RDONLY) = 3
13:00:36 fcntl64(3, F_GETFD) = 0
13:00:36 fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
.
.
.
13:00:36 read(3, "127.0.0.1\tlocalhost.localdomain\t"..., 4096) = 95
13:00:36 read(3, "", 4096) = 0
13:00:36 close(3) = 0
13:00:36 munmap(0x4009b000, 4096) = 0
13:00:36 brk(0x8293000) = 0x8293000
13:00:36 brk(0x82a4000) = 0x82a4000
13:00:36 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 3
13:00:36 connect(3, {sin_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("192.168.1.1")}}, 28) = 0
13:00:36 send(3, "\317\311\1\0\0\1\0\0\0\0\0\0\6sparge\4sill\0\0\34\0\1", 29, 0) = 29
13:00:36 gettimeofday({1058374836, 852482}, NULL) = 0
13:00:36 poll([{fd=3, events=POLLIN}], 1, 5000) = 0
13:00:41 send(3, "\317\311\1\0\0\1\0\0\0\0\0\0\6sparge\4sill\0\0\34\0\1", 29, 0) = 29
13:00:41 gettimeofday({1058374841, 862394}, NULL) = 0
13:00:41 poll([{fd=3, events=POLLIN}], 1, 5000) = 0
13:00:46 close(3) = 0
13:00:46 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 3
13:00:46 connect(3, {sin_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("192.168.1.1")}}, 28) = 0
13:00:46 send(3, "\317\312\1\0\0\1\0\0\0\0\0\0\6sparge\0\0\34\0\1", 24, 0) = 24
13:00:46 gettimeofday({1058374846, 873078}, NULL) = 0
13:00:46 poll([{fd=3, events=POLLIN}], 1, 5000) = 0
13:00:51 send(3, "\317\312\1\0\0\1\0\0\0\0\0\0\6sparge\0\0\34\0\1", 24, 0) = 24
13:00:51 gettimeofday({1058374851, 885677}, NULL) = 0
13:00:51 poll([{fd=3, events=POLLIN}], 1, 5000) = 0
13:00:56 close(3) = 0
13:00:56 brk(0x8282000) = 0x8282000
13:00:56 socket(PF_UNIX, SOCK_STREAM, 0) = 3
13:00:56 connect(3, {sin_family=AF_UNIX, path="/var/run/.nscd_socket"}, 110) = -1
ENOENT (No such file or directory)
13:00:56 close(3) = 0
13:00:56 open("/etc/hosts", O_RDONLY) = 3
13:00:56 fcntl64(3, F_GETFD) = 0
13:00:56 fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
.
.
.
13:00:56 connect(5, {sin_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("192.168.1.1")}}, 28) = 0
13:00:56 send(5, "\317\313\1\0\0\1\0\0\0\0\0\0\6sparge\4sill\0\0\34\0\1", 29, 0) = 29
13:00:56 gettimeofday({1058374856, 907120}, NULL) = 0
13:00:56 poll([{fd=5, events=POLLIN}], 1, 5000) = 0
13:01:01 send(5, "\317\313\1\0\0\1\0\0\0\0\0\0\6sparge\4sill\0\0\34\0\1", 29, 0) = 29
13:01:01 gettimeofday({1058374861, 914044}, NULL) = 0
13:01:01 poll([{fd=5, events=POLLIN}], 1, 5000) = 0
13:01:06 close(5) = 0
13:01:06 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 5
13:01:06 connect(5, {sin_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("192.168.1.1")}}, 28) = 0
13:01:06 send(5, "\317\314\1\0\0\1\0\0\0\0\0\0\6sparge\0\0\34\0\1", 24, 0) = 24
13:01:06 gettimeofday({1058374866, 924947}, NULL) = 0
13:01:06 poll([{fd=5, events=POLLIN}], 1, 5000) = 0
13:01:11 send(5, "\317\314\1\0\0\1\0\0\0\0\0\0\6sparge\0\0\34\0\1", 24, 0) = 24
13:01:11 gettimeofday({1058374871, 935061}, NULL) = 0
13:01:11 poll([{fd=5, events=POLLIN}], 1, 5000) = 0
13:01:16 close(5) = 0
13:01:16 munmap(0x4018d000, 4096) = 0
13:01:16 send(3, "ehlo sparge.sill\r\n", 18, 0) = 18
13:01:16 read(4, "250-sill.org\r\n250-PIPELINING\r\n25"..., 4096) = 58
13:01:16 send(3, "mail FROM:<[EMAIL PROTECTED]>\r\n", 30, 0) = 30
13:01:16 read(4, "250 ok\r\n", 4096) = 8
13:01:16 send(3, "rcpt TO:<[EMAIL PROTECTED]>\r\n", 28, 0) = 28
13:01:16 read(4, "250 ok\r\n", 4096) = 8
13:01:16 send(3, "data\r\n", 6, 0) = 6
13:01:16 read(4, "354 go ahead\r\n", 4096) = 14
13:01:16 brk(0x8284000) = 0x8284000
13:01:16 send(3, "Received: by sparge.sill (tmda-s"..., 7029, 0) = 7029
13:01:16 read(4, "250 ok 1058374877 qp 23996\r\n", 4096) = 28
13:01:17 send(3, "quit\r\n", 6, 0) = 6
13:01:17 read(4, "221 sill.org\r\n", 4096) = 14
13:01:17 close(4) = 0
13:01:17 munmap(0x4009b000, 4096) = 0
13:01:17 close(3) = 0
13:01:17 rt_sigaction(SIGINT, NULL, {SIG_IGN}, 8) = 0
13:01:17 rt_sigaction(SIGINT, {SIG_DFL}, NULL, 8) = 0
13:01:17 _exit(0) = ?
Anyone see anything strange? I can provide the full 300KB strace log
to anyone who wants it.
-Dave
_____________________________________________
tmda-users mailing list ([EMAIL PROTECTED])
http://tmda.net/lists/listinfo/tmda-users
