uh oh, think i found a problem...

Chris Aseltine ophidian@newsnation.com
Thu Apr 15 14:33:15 UTC 2010


So I took your advice and started sending myself duplicate instances of 
the same message from my Yahoo and Gmail accounts.  The Fuz1 and Fuz2 (and 
sometimes Body) counts eventually started rising, but once they got to 10, 
I stopped receiving the email in my mailbox.  This is even with my 
.procmailrc renamed away.  The mail log looks like this:

Apr 15 09:18:35 dakota sendmail[27942]: o3FEIYYV027942: from=<chris.aseltine@gmail.com>, size=4667, class=0, nrcpts=1, msgid=<z2j3e113b2d1004150718l3d375697n7363261713cd3a02@mail.gmail.com>, proto=ESMTP, daemon=Daemon4, relay=mail-wy0-f171.google.com [74.125.82.171]
Apr 15 09:18:35 dakota sendmail[27942]: o3FEIYYV027942: Milter delete: rcpt <ophidian@newsnation.com>
Apr 15 09:18:35 dakota sendmail[27942]: o3FEIYYV027942: Milter add: header: X-DCC--Metrics: dakota 1282; bulk Body=6 Fuz1=13 Fuz2=13
Apr 15 09:18:35 dakota sendmail[27942]: o3FEIYYV027942: Milter insert (1): header: Authentication-Results:  dakota.newsnation.com; dkim=pass (1024-bit key)\n\theader.i=@gmail.com; x-dkim-adsp=none
Apr 15 09:18:35 dakota sendmail[27942]: o3FEIYYV027942: Milter insert (1): header: X-DKIM:  Sendmail DKIM Filter v2.8.3 dakota.newsnation.com o3FEIYYV027942
Apr 15 09:18:35 dakota sendmail[27942]: o3FEIYYV027942: Milter insert (1): header: Authentication-Results:  dakota.newsnation.com; domainkeys=pass (testing) header.from=chris.aseltine@gmail.com
Apr 15 09:18:35 dakota sendmail[27942]: o3FEIYYV027942: Milter insert (1): header: X-DomainKeys:  Sendmail DomainKeys Filter v1.0.2 dakota.newsnation.com o3FEIYYV027942

Note that the "bulk" keyword properly appears.  However, no line like the 
following ever comes in the log:

Apr 15 09:15:18 dakota sendmail[27831]: o3FEFGgF027824: to=<ophidian@newsnation.com>, delay=00:00:01, xdelay=00:00:01, mailer=local, pri=32024, dsn=2.0.0, stat=Sent

...unlike the first nine messages, which were actually delivered. 
Further, if I look in my Yahoo or Gmail accounts, there is no bounce 
message of any kind.  So it looks like all bulk mail on my system is being 
silently discarded.  Which, of course, is bad.

Now, another thing is when the mail delivery process gets in this state, I 
see sendmail lingering for quite some time in the process list:

28104 ?        S      0:00 sendmail: server mail-ww0-f43.google.com [74.125.82.43] cmd read

Wondering what it was up to, I used strace -p and found it was blocking on 
a select() call, and then eventually finishes with the following:

=======

[root@dakota /home/ophidian]$ strace -p 28104
Process 28104 attached - interrupt to quit
select(12, [11], NULL, [11], {3582, 728000}

) = 1 (in [11], left {3569, 884000})
gettimeofday({1271341685, 279917}, NULL) = 0
read(11, "QUIT\r\n", 4096)              = 6
fcntl64(3, F_GETFL)                     = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl64(3, F_SETFL, O_RDWR)             = 0
write(3, "221 2.0.0 dakota.newsnation.com "..., 52) = 52
rt_sigaction(SIGINT, {SIG_IGN}, {SIG_IGN}, 8) = 0
rt_sigaction(SIGQUIT, {SIG_IGN}, {SIG_IGN}, 8) = 0
rt_sigprocmask(SIG_BLOCK, NULL, [], 8)  = 0
rt_sigprocmask(SIG_BLOCK, [ALRM], [], 8) = 0
time(NULL)                              = 1271341685
rt_sigaction(SIGALRM, {0x80bd5c0, [], SA_RESTART}, {0x80bd5c0, [], 
SA_RESTART}, 8) = 0
alarm(3600)                             = 0
rt_sigprocmask(SIG_UNBLOCK, [ALRM], [ALRM], 8) = 0
close(11)                               = 0
rt_sigprocmask(SIG_BLOCK, [ALRM], [], 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [ALRM], [ALRM], 8) = 0
alarm(0)                                = 3600
close(0)                                = 0
open("/dev/null", O_RDONLY)             = 0
close(3)                                = 0
open("/dev/null", O_WRONLY)             = 3
dup2(3, 1)                              = 1
dup2(3, 2)                              = 2
close(3)                                = 0
fstat64(0, {st_mode=S_IFCHR|0666, st_rdev=makedev(1, 3), ...}) = 0
fstat64(1, {st_mode=S_IFCHR|0666, st_rdev=makedev(1, 3), ...}) = 0
fstat64(2, {st_mode=S_IFCHR|0666, st_rdev=makedev(1, 3), ...}) = 0
time(NULL)                              = 1271341685
select(6, NULL, [5], NULL, {30, 0})     = 1 (out [5], left {30, 0})
writev(5, [{"\0\0\0\1Q", 5}], 1)        = 5
close(5)                                = 0
time(NULL)                              = 1271341685
select(7, NULL, [6], NULL, {10, 0})     = 1 (out [6], left {10, 0})
writev(6, [{"\0\0\0\1Q", 5}], 1)        = 5
close(6)                                = 0
time(NULL)                              = 1271341685
select(8, NULL, [7], NULL, {10, 0})     = 1 (out [7], left {10, 0})
writev(7, [{"\0\0\0\1Q", 5}], 1)        = 5
close(7)                                = 0
alarm(0)                                = 0
rt_sigprocmask(SIG_UNBLOCK, [ALRM], [], 8) = 0
time(NULL)                              = 1271341685
time(NULL)                              = 1271341685
unlink("./dfo3FERYmO028104")            = -1 ENOENT (No such file or directory)
unlink("./qfo3FERYmO028104")            = -1 ENOENT (No such file or directory)
unlink("./xfo3FERYmO028104")            = -1 ENOENT (No such file or directory)
setuid32(0)                             = 0
exit_group(0)                           = ?
Process 28104 detached

====

Does this mean anything?  What could be going on here?

-Chris



More information about the DCC mailing list

Contact vjs@rhyolite.com by mail or use the form.