Here is another abnormal delivery, this time with strace for the spamd
child.
The relevant part of the strace seems to be:
connect(8, {sa_family=AF_INET, sin_port=htons(113),
sin_addr=inet_addr("127.0.0.1")}, 16) = -1 EINPROGRESS (Operation now in
progress)
--
Troy
==> exim4/mainlog <==
2010-03-18 09:27:58 1NsGha-0001bC-QE <= [email protected] H=localhost
(MYDOMAIN.NET) [127.0.0.1] U=troy P=esmtp S=1549
[email protected]
2010-03-18 09:27:58 1NsGha-0001bC-QE => troy <t...@localhost> R=procmail
T=procmail_pipe
2010-03-18 09:27:58 1NsGha-0001bC-QE Completed
===> syslog <===
Mar 18 09:27:58 tiferet oidentd[6151]: Connection from localhost
(127.0.0.1):47195
Mar 18 09:27:58 tiferet oidentd[6151]: [localhost] Successful lookup: 52558 ,
25 : troy (troy)
Mar 18 09:27:58 tiferet spamd[5274]: prefork: ordered 5281 to accept
Mar 18 09:27:58 tiferet spamd[5281]: spamd: connection from localhost
[127.0.0.1] at port 53746
Mar 18 09:27:58 tiferet oidentd[6158]: Connection from localhost
(127.0.0.1):46405
Mar 18 09:27:58 tiferet spamd[5281]: ident: ident_username = NONE,
spamc_username = troy
Mar 18 09:27:58 tiferet spamd[5281]: spamd: ident username (NONE) does not
match spamc username (troy)
Mar 18 09:27:58 tiferet spamd[5274]: prefork: child 5281: entering state 2
Mar 18 09:27:58 tiferet spamd[5281]: config: copying current conf from backup
Mar 18 09:27:58 tiferet spamd[5274]: prefork: new lowest idle kid: 5282
Mar 18 09:27:59 tiferet spamd[5281]: timing: total 77 ms - copy_config: 77
(100.0%)
Mar 18 09:27:59 tiferet spamd[5274]: prefork: child 5281: entering state 1
Mar 18 09:27:59 tiferet spamd[5281]: prefork: sysread(7) not ready, wait max
300 secs
Mar 18 09:27:59 tiferet spamd[5274]: prefork: new lowest idle kid: 5281
Mar 18 09:27:59 tiferet spamd[5274]: prefork: child reports idle
Mar 18 09:27:59 tiferet spamd[5274]: prefork: child states: II
==> /tmp/spamd-debug.txt <==
Mar 18 09:27:58.967 [5281] info: spamd: connection from localhost [127.0.0.1]
at port 53746
Mar 18 09:27:58.972 [5281] dbg: ident: ident_username = NONE, spamc_username =
troy
Mar 18 09:27:58.974 [5281] info: spamd: ident username (NONE) does not match
spamc username (troy)
Mar 18 09:27:58.979 [5281] dbg: config: copying current conf from backup
Mar 18 09:27:59.056 [5281] dbg: timing: total 77 ms - copy_config: 77 (100.0%)
Mar 18 09:27:59.059 [5281] dbg: prefork: sysread(7) not ready, wait max 300 secs
==> /tmp/spamd-strace.txt.5281 <==
accept(5, {sa_family=AF_INET, sin_port=htons(53746),
sin_addr=inet_addr("127.0.0.1")}, [16]) = 6
ioctl(6, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbfa0bb18) = -1
EINVAL (Invalid argument)
_llseek(6, 0, 0xbfa0bb60, SEEK_CUR) = -1 ESPIPE (Illegal seek)
ioctl(6, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbfa0bb18) = -1 EINVAL (Invalid
argument)
_llseek(6, 0, 0xbfa0bb60, SEEK_CUR) = -1 ESPIPE (Illegal seek)
fcntl64(6, F_SETFD, FD_CLOEXEC) = 0
write(7, "B\0\0\24\241\n", 6) = 6
getpeername(6, {sa_family=AF_INET, sin_port=htons(53746),
sin_addr=inet_addr("127.0.0.1")}, [16]) = 0
gettimeofday({1268922478, 964348}, NULL) = 0
getpeername(6, {sa_family=AF_INET, sin_port=htons(53746),
sin_addr=inet_addr("127.0.0.1")}, [16]) = 0
open("/etc/hosts", O_RDONLY|O_CLOEXEC) = 8
fstat64(8, {st_mode=S_IFREG|0644, st_size=300, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
0xb77bc000
read(8, "127.0.0.1\tlocalhost\n127.0.0.1\tca"..., 4096) = 300
close(8) = 0
munmap(0xb77bc000, 4096) = 0
open("/etc/services", O_RDONLY|O_CLOEXEC) = 8
fstat64(8, {st_mode=S_IFREG|0644, st_size=19226, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
0xb77bc000
read(8, "# Network services, Internet sty"..., 4096) = 4096
read(8, "9/tcp\t\t\t\t# Quick Mail Transfer P"..., 4096) = 4096
read(8, "4/udp\nrmiregistry\t1099/tcp\t\t\t# J"..., 4096) = 4096
read(8, "_execd\t6445/tcp\t\t\t# Grid Engine "..., 4096) = 4096
read(8, " predict -- satellite tracking\nr"..., 4096) = 2842
read(8, "", 4096) = 0
close(8) = 0
munmap(0xb77bc000, 4096) = 0
gettimeofday({1268922478, 967461}, NULL) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
time(NULL) = 1268922478
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
write(2, "Mar 18 09:27:58.967 [5281] info:"..., 92) = 92
rt_sigprocmask(SIG_BLOCK, [PIPE], [], 8) = 0
rt_sigaction(SIGPIPE, {SIG_DFL, [], 0}, {SIG_IGN, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [PIPE], [], 8) = 0
rt_sigaction(SIGPIPE, {0x80c4d80, [], 0}, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
time(NULL) = 1268922478
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
time(NULL) = 1268922478
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
select(8, [4], NULL, [4], {0, 0}) = 0 (Timeout)
write(4, "<22>Mar 18 09:27:58 spamd[5281]:"..., 93) = 93
rt_sigprocmask(SIG_BLOCK, [PIPE], [], 8) = 0
rt_sigaction(SIGPIPE, {SIG_IGN, [], 0}, {0x80c4d80, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [PIPE], [], 8) = 0
rt_sigaction(SIGPIPE, {SIG_IGN, [], 0}, {SIG_IGN, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1], [], 8) = 0
rt_sigprocmask(SIG_BLOCK, [ALRM], ~[KILL STOP RTMIN RT_1], 8) = 0
rt_sigaction(SIGALRM, {0x80c4d80, [], 0}, {0x80c4d80, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, ~[KILL STOP RTMIN RT_1], NULL, 8) = 0
rt_sigaction(SIGALRM, {0x80c4580, [], 0}, NULL, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
alarm(30) = 0
read(6, "PROCESS SPAMC/1.5\r\nUser: troy\r\nC"..., 4096) = 1769
alarm(0) = 30
rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1], [], 8) = 0
rt_sigprocmask(SIG_BLOCK, [ALRM], ~[KILL STOP RTMIN RT_1], 8) = 0
rt_sigaction(SIGALRM, {0x80c4d80, [], 0}, {0x80c4580, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, ~[KILL STOP RTMIN RT_1], NULL, 8) = 0
rt_sigaction(SIGALRM, {0x80c4580, [], 0}, NULL, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
alarm(300) = 0
getsockname(6, {sa_family=AF_INET, sin_port=htons(783),
sin_addr=inet_addr("127.0.0.1")}, [16]) = 0
getpeername(6, {sa_family=AF_INET, sin_port=htons(53746),
sin_addr=inet_addr("127.0.0.1")}, [16]) = 0
time(NULL) = 1268922478
socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 8
ioctl(8, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbfa0cb18) = -1 EINVAL (Invalid
argument)
_llseek(8, 0, 0xbfa0cb60, SEEK_CUR) = -1 ESPIPE (Illegal seek)
ioctl(8, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbfa0cb18) = -1 EINVAL (Invalid
argument)
_llseek(8, 0, 0xbfa0cb60, SEEK_CUR) = -1 ESPIPE (Illegal seek)
fcntl64(8, F_SETFD, FD_CLOEXEC) = 0
bind(8, {sa_family=AF_INET, sin_port=htons(0),
sin_addr=inet_addr("127.0.0.1")}, 16) = 0
fcntl64(8, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
connect(8, {sa_family=AF_INET, sin_port=htons(113),
sin_addr=inet_addr("127.0.0.1")}, 16) = -1 EINPROGRESS (Operation now in
progress)
close(8) = 0
gettimeofday({1268922478, 972093}, NULL) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
time(NULL) = 1268922478
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
write(2, "Mar 18 09:27:58.972 [5281] dbg: "..., 84) = 84
rt_sigprocmask(SIG_BLOCK, [PIPE], [], 8) = 0
rt_sigaction(SIGPIPE, {SIG_DFL, [], 0}, {SIG_IGN, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [PIPE], [], 8) = 0
rt_sigaction(SIGPIPE, {0x80c4d80, [], 0}, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
time(NULL) = 1268922478
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
time(NULL) = 1268922478
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
select(8, [4], NULL, [4], {0, 0}) = 0 (Timeout)
write(4, "<23>Mar 18 09:27:58 spamd[5281]:"..., 86) = 86
rt_sigprocmask(SIG_BLOCK, [PIPE], [], 8) = 0
rt_sigaction(SIGPIPE, {SIG_IGN, [], 0}, {0x80c4d80, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [PIPE], [], 8) = 0
rt_sigaction(SIGPIPE, {SIG_IGN, [], 0}, {SIG_IGN, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
gettimeofday({1268922478, 974388}, NULL) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
time(NULL) = 1268922478
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
write(2, "Mar 18 09:27:58.974 [5281] info:"..., 99) = 99
rt_sigprocmask(SIG_BLOCK, [PIPE], [], 8) = 0
rt_sigaction(SIGPIPE, {SIG_DFL, [], 0}, {SIG_IGN, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [PIPE], [], 8) = 0
rt_sigaction(SIGPIPE, {0x80c4d80, [], 0}, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
time(NULL) = 1268922478
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
time(NULL) = 1268922478
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
select(8, [4], NULL, [4], {0, 0}) = 0 (Timeout)
write(4, "<22>Mar 18 09:27:58 spamd[5281]:"..., 100) = 100
rt_sigprocmask(SIG_BLOCK, [PIPE], [], 8) = 0
rt_sigaction(SIGPIPE, {SIG_IGN, [], 0}, {0x80c4d80, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [PIPE], [], 8) = 0
rt_sigaction(SIGPIPE, {SIG_IGN, [], 0}, {SIG_IGN, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
alarm(0) = 300
_llseek(6, 31, 0xbfa0cbb0, SEEK_SET) = -1 ESPIPE (Illegal seek)
close(6) = 0
gettimeofday({1268922478, 977394}, NULL) = 0
alarm(0) = 0
rt_sigprocmask(SIG_BLOCK, [ALRM], [], 8) = 0
rt_sigaction(SIGALRM, {SIG_DFL, [], 0}, {0x80c4580, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [ALRM], [], 8) = 0
rt_sigaction(SIGALRM, {0x80c4d80, [], 0}, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
alarm(20) = 0
gettimeofday({1268922478, 978729}, NULL) = 0
gettimeofday({1268922478, 978956}, NULL) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
time(NULL) = 1268922478
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
write(2, "Mar 18 09:27:58.979 [5281] dbg: "..., 73) = 73
rt_sigprocmask(SIG_BLOCK, [PIPE], [], 8) = 0
rt_sigaction(SIGPIPE, {SIG_DFL, [], 0}, {SIG_IGN, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [PIPE], [], 8) = 0
rt_sigaction(SIGPIPE, {0x80c4d80, [], 0}, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
time(NULL) = 1268922478
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
time(NULL) = 1268922478
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
select(8, [4], NULL, [4], {0, 0}) = 0 (Timeout)
write(4, "<23>Mar 18 09:27:58 spamd[5281]:"..., 75) = 75
rt_sigprocmask(SIG_BLOCK, [PIPE], [], 8) = 0
rt_sigaction(SIGPIPE, {SIG_IGN, [], 0}, {0x80c4d80, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [PIPE], [], 8) = 0
rt_sigaction(SIGPIPE, {SIG_IGN, [], 0}, {SIG_IGN, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
gettimeofday({1268922479, 55379}, NULL) = 0
rt_sigprocmask(SIG_BLOCK, [ALRM], [], 8) = 0
rt_sigaction(SIGALRM, {0x80c4d80, [], 0}, {0x80c4d80, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
alarm(0) = 20
gettimeofday({1268922479, 55943}, NULL) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
time(NULL) = 1268922479
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
write(2, "Mar 18 09:27:59.056 [5281] dbg: "..., 79) = 79
rt_sigprocmask(SIG_BLOCK, [PIPE], [], 8) = 0
rt_sigaction(SIGPIPE, {SIG_DFL, [], 0}, {SIG_IGN, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [PIPE], [], 8) = 0
rt_sigaction(SIGPIPE, {0x80c4d80, [], 0}, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
time(NULL) = 1268922479
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
time(NULL) = 1268922479
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
select(8, [4], NULL, [4], {0, 0}) = 0 (Timeout)
write(4, "<23>Mar 18 09:27:59 spamd[5281]:"..., 81) = 81
rt_sigprocmask(SIG_BLOCK, [PIPE], [], 8) = 0
rt_sigaction(SIGPIPE, {SIG_IGN, [], 0}, {0x80c4d80, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [PIPE], [], 8) = 0
rt_sigaction(SIGPIPE, {SIG_IGN, [], 0}, {SIG_IGN, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
write(7, "I\0\0\24\241\n", 6) = 6
read(7, 0xa322c78, 6) = -1 EAGAIN (Resource temporarily unavailable)
time(NULL) = 1268922479
gettimeofday({1268922479, 59245}, NULL) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
time(NULL) = 1268922479
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
write(2, "Mar 18 09:27:59.059 [5281] dbg: "..., 81) = 81
rt_sigprocmask(SIG_BLOCK, [PIPE], [], 8) = 0
rt_sigaction(SIGPIPE, {SIG_DFL, [], 0}, {SIG_IGN, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [PIPE], [], 8) = 0
rt_sigaction(SIGPIPE, {0x80c4d80, [], 0}, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
time(NULL) = 1268922479
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
time(NULL) = 1268922479
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3543, ...}) = 0
select(8, [4], NULL, [4], {0, 0}) = 0 (Timeout)
write(4, "<23>Mar 18 09:27:59 spamd[5281]:"..., 83) = 83
rt_sigprocmask(SIG_BLOCK, [PIPE], [], 8) = 0
rt_sigaction(SIGPIPE, {SIG_IGN, [], 0}, {0x80c4d80, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [PIPE], [], 8) = 0
rt_sigaction(SIGPIPE, {SIG_IGN, [], 0}, {SIG_IGN, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
select(8, [7], NULL, NULL, {300, 0}
--
To UNSUBSCRIBE, email to [email protected]
with a subject of "unsubscribe". Trouble? Contact [email protected]
