mlmmj-send processes eating cpu

mlmmj-send processes eating cpu

[Nate Beaty]

I noticed today my server was creeping along, and top shows multiple  
mlmmj-send instances running:

   PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
12707 Debian-e  25   0  1700  656  576 R 19.8  0.1 343:26.36 mlmmj-send
19468 Debian-e  25   0  1700  660  576 R 18.1  0.1  10:11.16 mlmmj-send
  8615 Debian-e  25   0  1712  676  584 R 17.8  0.1  29:10.13 mlmmj-send
19469 Debian-e  25   0  1700  656  576 R 16.8  0.1  10:10.91 mlmmj-send
  8618 Debian-e  25   0  1704  664  576 R 16.5  0.1  29:10.66 mlmmj-send

Yesterday a client sent out newsletters to some large lists (some  
over 20,000, most around 1-2,000) which seemed to go fine for the  
most part. But now I have these mlmmj-send processes stuck eating all  
my CPU. Any idea of why or how to troubleshoot this?

This is with the latest 1.2.12RC2 release, Exim4, dnsmasq.

Any help much appreciated. (And I still haven't gotten the new submod  
tunable to work for me, either...)

Nate.

--
Clixel Design & Coding ~ http://clixel.com/

Re: mlmmj-send processes eating cpu

[Mads Martin Joergensen]

* Nate Beaty <natebeaty@gmail.com> [Sep 16. 2006 20:29]:
> I noticed today my server was creeping along, and top shows multiple  
> mlmmj-send instances running:
> 
>   PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
> 12707 Debian-e  25   0  1700  656  576 R 19.8  0.1 343:26.36 mlmmj-send
> 19468 Debian-e  25   0  1700  660  576 R 18.1  0.1  10:11.16 mlmmj-send
>  8615 Debian-e  25   0  1712  676  584 R 17.8  0.1  29:10.13 mlmmj-send
> 19469 Debian-e  25   0  1700  656  576 R 16.8  0.1  10:10.91 mlmmj-send
>  8618 Debian-e  25   0  1704  664  576 R 16.5  0.1  29:10.66 mlmmj-send
> 
> Yesterday a client sent out newsletters to some large lists (some  
> over 20,000, most around 1-2,000) which seemed to go fine for the  
> most part. But now I have these mlmmj-send processes stuck eating all  
> my CPU. Any idea of why or how to troubleshoot this?
> 
> This is with the latest 1.2.12RC2 release, Exim4, dnsmasq.
> 
> Any help much appreciated. (And I still haven't gotten the new submod  
> tunable to work for me, either...)

Can you attach an strace to one of those, seing what it does?

-- 
Mads Martin Joergensen, http://mmj.dk
"Why make things difficult, when it is possible to make them cryptic
 and totally illogical, with just a little bit more effort?"
                                 -- A. P. J.

Re: mlmmj-send processes eating cpu

[Nate Beaty]

On Sep 16, 2006, at 12:12 PM, Mads Martin Joergensen wrote:

> Can you attach an strace to one of those, seing what it does?

I actually rebooted my server before getting this message. But a day  
later, mlmmj-send has 2 processes in top:

   PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
21593 Debian-e  25   0  1700  656  576 R 53.4  0.1  39:19.81 mlmmj-send
21636 Debian-e  25   0  1704  660  576 R 42.0  0.1  39:16.27 mlmmj-send

I'm not sure which options you want me to use on strace, but here's  
what shows:

 > sudo strace -p 21593
Process 21593 attached - interrupt to quit
read(7, "", 512)                        = 0
read(7, "", 512)                        = 0
read(7, "", 512)                        = 0
read(7, "", 512)                        = 0
read(7, "", 512)                        = 0
read(7, "", 512)                        = 0
read(7, "", 512)                        = 0
...

 > sudo strace -v -T -p 21636
Process 21636 attached - interrupt to quit
read(7, "", 512)                        = 0 <0.000322>
read(7, "", 512)                        = 0 <0.000182>
read(7, "", 512)                        = 0 <0.000134>
read(7, "", 512)                        = 0 <0.000145>
read(7, "", 512)                        = 0 <0.000197>
read(7, "", 512)                        = 0 <0.000146>
read(7, "", 512)                        = 0 <0.000164>
read(7, "", 512)                        = 0 <0.000215>
read(7, "", 512)                        = 0 <0.000146>

Does that help? I'm new to strace and reading through man strace I  
couldn't find anything to make more sense of the above output.

Thanks,
Nate.

--
Clixel Design & Coding ~ http://clixel.com/

Re: mlmmj-send processes eating cpu

[Sven 'Darkman' Michels]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Hi,

Nate Beaty wrote:
>> sudo strace -p 21593
> Process 21593 attached - interrupt to quit
> read(7, "", 512)                        = 0
> read(7, "", 512)                        = 0
> read(7, "", 512)                        = 0
> read(7, "", 512)                        = 0
> read(7, "", 512)                        = 0
> read(7, "", 512)                        = 0
> read(7, "", 512)                        = 0
> ...
> 
>> sudo strace -v -T -p 21636
> Process 21636 attached - interrupt to quit
> read(7, "", 512)                        = 0 <0.000322>
> read(7, "", 512)                        = 0 <0.000182>
> read(7, "", 512)                        = 0 <0.000134>
> read(7, "", 512)                        = 0 <0.000145>
> read(7, "", 512)                        = 0 <0.000197>
> read(7, "", 512)                        = 0 <0.000146>
> read(7, "", 512)                        = 0 <0.000164>
> read(7, "", 512)                        = 0 <0.000215>
> read(7, "", 512)                        = 0 <0.000146>
> 
> Does that help? I'm new to strace and reading through man strace I
> couldn't find anything to make more sense of the above output.

Can you please check which fd 7 is? (/proc/$PID/fd)

Regards,
Sven
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.5 (MingW32)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iD8DBQFFDXyvQoCguWUBzBwRAvBpAKCaGgueJbGAHBR6JqFnPGZ8jHaa+ACdGNkJ
BjMabJxEiMMwBbCtkzej+3M=JedV
-----END PGP SIGNATURE-----

Re: mlmmj-send processes eating cpu

[Nate Beaty]

On Sep 17, 2006, at 9:49 AM, Sven 'Darkman' Michels wrote:

> Can you please check which fd 7 is? (/proc/$PID/fd)

 > sudo ls -la /proc/21636/fd
total 9
dr-x------ 2 Debian-exim root  0 2006-09-17 09:44 .
dr-xr-xr-x 5 Debian-exim root  0 2006-09-17 08:05 ..
lr-x------ 1 Debian-exim root 64 2006-09-17 09:45 0 -> pipe:[725488]
l-wx------ 1 Debian-exim root 64 2006-09-17 09:45 1 -> pipe:[725489]
l-wx------ 1 Debian-exim root 64 2006-09-17 09:45 2 -> pipe:[725489]
lr-x------ 1 Debian-exim root 64 2006-09-17 09:45 3 -> /var/spool/ 
mlmmj/topshelf-newsletter/text/bounce-probe
l-wx------ 1 Debian-exim root 64 2006-09-17 09:45 4 -> /var/spool/ 
mlmmj/topshelf-newsletter/maintdlog-cac9de92e092a5c
l-wx------ 1 Debian-exim root 64 2006-09-17 09:45 5 -> /var/spool/ 
mlmmj/topshelf-newsletter/bounce/erinn.hartman=us.penguingroup.com-probe
lrwx------ 1 Debian-exim root 64 2006-09-17 09:45 6 -> /var/spool/ 
mlmmj/topshelf-newsletter/queue/950c4a8771dfca7
lrwx------ 1 Debian-exim root 64 2006-09-17 09:44 7 -> socket:[728893]
lrwx------ 1 Debian-exim root 64 2006-09-17 09:45 8 -> socket:[728895]

I'm learning as we go here.. anything else I can do?

Nate.

--
Clixel Design & Coding ~ http://clixel.com/

Re: mlmmj-send processes eating cpu

[Sven 'Darkman' Michels]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Nate Beaty wrote:
> lrwx------ 1 Debian-exim root 64 2006-09-17 09:44 7 -> socket:[728893]
> lrwx------ 1 Debian-exim root 64 2006-09-17 09:45 8 -> socket:[728895]
> 
> I'm learning as we go here.. anything else I can do?

so its a socket... lsof -n | grep 728893 i'd check now...

Regards,
Darkman
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.2.2 (GNU/Linux)

iD8DBQFFDYL+QoCguWUBzBwRAgbNAJ9k/6DbGABsvBFFkzSDXFiCsva8nACgpgM5
m7T8MUblblKoJw2KIqgo4N0=yfjp
-----END PGP SIGNATURE-----

Re: mlmmj-send processes eating cpu

[Nate Beaty]

On Sep 17, 2006, at 10:16 AM, Sven 'Darkman' Michels wrote:

> so its a socket... lsof -n | grep 728893 i'd check now...

 > sudo lsof -n | grep 728893
mlmmj-sen 21636 Debian-exim    7u     sock        0,4               
728893 can't identify protocol

Thanks,
Nate.

--
Clixel Design & Coding ~ http://clixel.com/

Re: mlmmj-send processes eating cpu

[Nate Beaty]

Sorry for all the posts.. but I seem to have run into a few problems  
that my feeble troubleshooting skills aren't figuring out.

mlmmj-send is still consuming all my CPU resources:

   PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
21636 Debian-e  25   0  1704  660  576 R 51.0  0.1 114:11.26 mlmmj-send
21593 Debian-e  25   0  1700  656  576 R 43.4  0.1 113:39.36 mlmmj-send

and this is what lsof shows for mlmmj-send:

 > sudo lsof -c mlmmj-send
COMMAND     PID        USER   FD   TYPE     DEVICE    SIZE     NODE NAME
mlmmj-sen 21593 Debian-exim  cwd    DIR        3,1   77824   803937 / 
var/spool/mlmmj/topshelf-newsletter/bounce
mlmmj-sen 21593 Debian-exim  rtd    DIR        3,1    4096        2 /
mlmmj-sen 21593 Debian-exim  txt    REG        3,1   95242  8668935 / 
usr/bin/mlmmj-send
mlmmj-sen 21593 Debian-exim  mem    REG        0,0                0  
[heap] (stat: No such file or directory)
mlmmj-sen 21593 Debian-exim  mem    REG        3,1   37432 11174948 / 
lib/tls/i686/cmov/libnss_files-2.3.6.so
mlmmj-sen 21593 Debian-exim  mem    REG        3,1 1232784 11174931 / 
lib/tls/i686/cmov/libc-2.3.6.so
mlmmj-sen 21593 Debian-exim  mem    REG        3,1   77176 11174942 / 
lib/tls/i686/cmov/libnsl-2.3.6.so
mlmmj-sen 21593 Debian-exim  DEL-W  REG        3,1           818899 / 
var/spool/mlmmj/topshelf-newsletter/queue/1bd21e6678fb3eb0
mlmmj-sen 21593 Debian-exim  mem    REG        3,1   86404 11141141 / 
lib/ld-2.3.6.so
mlmmj-sen 21593 Debian-exim    0r  FIFO        0,5           725480 pipe
mlmmj-sen 21593 Debian-exim    1w  FIFO        0,5           725481 pipe
mlmmj-sen 21593 Debian-exim    2w  FIFO        0,5           725481 pipe
mlmmj-sen 21593 Debian-exim    3r   REG        3,1     339   803959 / 
var/spool/mlmmj/topshelf-newsletter/text/bounce-probe
mlmmj-sen 21593 Debian-exim    4w   REG        3,1     636   816911 / 
var/spool/mlmmj/topshelf-newsletter/maintdlog-78d7723696991ff
mlmmj-sen 21593 Debian-exim    5w   REG        3,1      10   817427 / 
var/spool/mlmmj/topshelf-newsletter/bounce/ 
w lgary.mcnallyrobinson.ca-probe
mlmmj-sen 21593 Debian-exim    6uW  REG        3,1     570   818899 / 
var/spool/mlmmj/topshelf-newsletter/queue/1bd21e6678fb3eb0 (deleted)
mlmmj-sen 21593 Debian-exim    7u  sock        0,4           728715  
can't identify protocol
mlmmj-sen 21593 Debian-exim    8u  unix 0xcf893b60           728717  
socket
mlmmj-sen 21636 Debian-exim  cwd    DIR        3,1   77824   803937 / 
var/spool/mlmmj/topshelf-newsletter/bounce
mlmmj-sen 21636 Debian-exim  rtd    DIR        3,1    4096        2 /
mlmmj-sen 21636 Debian-exim  txt    REG        3,1   95242  8668935 / 
usr/bin/mlmmj-send
mlmmj-sen 21636 Debian-exim  mem    REG        0,0                0  
[heap] (stat: No such file or directory)
mlmmj-sen 21636 Debian-exim  mem    REG        3,1   37432 11174948 / 
lib/tls/i686/cmov/libnss_files-2.3.6.so
mlmmj-sen 21636 Debian-exim  mem    REG        3,1 1232784 11174931 / 
lib/tls/i686/cmov/libc-2.3.6.so
mlmmj-sen 21636 Debian-exim  mem    REG        3,1   77176 11174942 / 
lib/tls/i686/cmov/libnsl-2.3.6.so
mlmmj-sen 21636 Debian-exim  DEL-W  REG        3,1           817302 / 
var/spool/mlmmj/topshelf-newsletter/queue/950c4a8771dfca7
mlmmj-sen 21636 Debian-exim  mem    REG        3,1   86404 11141141 / 
lib/ld-2.3.6.so
mlmmj-sen 21636 Debian-exim    0r  FIFO        0,5           725488 pipe
mlmmj-sen 21636 Debian-exim    1w  FIFO        0,5           725489 pipe
mlmmj-sen 21636 Debian-exim    2w  FIFO        0,5           725489 pipe
mlmmj-sen 21636 Debian-exim    3r   REG        3,1     339   803959 / 
var/spool/mlmmj/topshelf-newsletter/text/bounce-probe
mlmmj-sen 21636 Debian-exim    4w   REG        3,1     636   817065 / 
var/spool/mlmmj/topshelf-newsletter/maintdlog-cac9de92e092a5c
mlmmj-sen 21636 Debian-exim    5w   REG        3,1      10   818939 / 
var/spool/mlmmj/topshelf-newsletter/bounce/ 
erinn.hartman=us.penguingroup.com-probe
mlmmj-sen 21636 Debian-exim    6uW  REG        3,1     575   817302 / 
var/spool/mlmmj/topshelf-newsletter/queue/950c4a8771dfca7 (deleted)
mlmmj-sen 21636 Debian-exim    7u  sock        0,4           728893  
can't identify protocol
mlmmj-sen 21636 Debian-exim    8u  unix 0xcf893e20           728895  
socket


Also, a user just wrote complaining that he received 25 messages to a  
deactivated address that was on the list.. I asked him to send me a  
forward of one of the emails and how exactly the email was  
"deactivated", but haven't heard back from him. Looking at the Exim  
log, I see multiple attempts to send bounce probes:

2006-09-16 01:06:50 1GOVBe-0005cc-PA SA: Action: scanned but message  
isn't spam: score=-1.1 required=5.0 (scanned in 44/44 secs | Message- 
Id: 1158394616.8277@comicbookbin.com). From <editor@comicbookbin.com>  
(host=server296.com [216.35.196.11]) for topshelf-newsletter-media 
+bounces-probe-editor=comicbookbin.com@lists.clixel.com
2006-09-16 01:06:50 1GOVBe-0005cc-PA <= editor@comicbookbin.com  
H=server296.com [216.35.196.11] P=esmtps  
X=TLS-1.0:DHE_RSA_3DES_EDE_CBC_SHA1:24 S\x1610  
id\x1158394616.8277@comicbookbin.com
2006-09-16 01:13:02 1GOVBe-0005cc-PA => topshelf-newsletter-media  
<topshelf-newsletter-media+bounces-probe- 
editor=comicbookbin.com@lists.clixel.com> R=mlmmj_router  
T=mlmmj_transport
2006-09-16 02:00:58 1GOW2k-000836-1c SA: Action: Not running SA  
because SAEximRunCond expanded to false (Message-Id:  
1GOW2k-000836-1c). From <topshelf-newsletter-media+bounces-probe- 
editor=comicbookbin.com@lists.clixel.com> (host=localhost.localdomain  
[127.0.0.1]) for editor@comicbookbin.com
2006-09-16 02:00:58 1GOW2k-000836-1c <= topshelf-newsletter-media 
+bounces-probe-editor=comicbookbin.com@lists.clixel.com  
H=localhost.localdomain (mail.clixel.com) [127.0.0.1] P=smtp S\x1091  
id\x1158397258-5ccf044b-mlmmj-113a5496@15bacbfa.plonk
2006-09-16 02:04:46 1GOW2k-000836-1c => editor@comicbookbin.com  
R=dnslookup T=remote_smtp H=mail.comicbookbin.com [216.35.196.11]  
X=TLS-1.0:RSA_3DES_EDE_CBC_SHA1:24
2006-09-16 02:05:26 1GOW6U-00088b-Ke SA: Action: scanned but message  
isn't spam: score=-1.2 required=5.0 (scanned in 36/36 secs | Message- 
Id: 1158398142.21128@comicbookbin.com). From  
<editor@comicbookbin.com> (host=server296.com [216.35.196.11]) for  
topshelf-newsletter-media+bounces-probe- 
editor=comicbookbin.com@lists.clixel.com
2006-09-16 02:05:26 1GOW6U-00088b-Ke <= editor@comicbookbin.com  
H=server296.com [216.35.196.11] P=esmtps  
X=TLS-1.0:DHE_RSA_3DES_EDE_CBC_SHA1:24 S\x1611  
id\x1158398142.21128@comicbookbin.com
2006-09-16 04:24:36 1GOW6U-00088b-Ke => topshelf-newsletter-media  
<topshelf-newsletter-media+bounces-probe- 
editor=comicbookbin.com@lists.clixel.com> R=mlmmj_router  
T=mlmmj_transport
2006-09-16 06:01:00 1GOZn2-0007oY-HY SA: Action: Not running SA  
because SAEximRunCond expanded to false (Message-Id: 1GOZn2-0007oY- 
HY). From <topshelf-newsletter-media+bounces-probe- 
editor=comicbookbin.com@lists.clixel.com> (host=localhost.localdomain  
[127.0.0.1]) for editor@comicbookbin.com
2006-09-16 06:01:00 1GOZn2-0007oY-HY <= topshelf-newsletter-media 
+bounces-probe-editor=comicbookbin.com@lists.clixel.com  
H=localhost.localdomain (mail.clixel.com) [127.0.0.1] P=smtp S\x1091  
id\x1158411660-2eb58a36-mlmmj-16afa0bd@684868ac.plonk
2006-09-16 06:52:48 1GOZn2-0007oY-HY => editor@comicbookbin.com  
R=dnslookup T=remote_smtp H=mail.comicbookbin.com [216.35.196.11]  
X=TLS-1.0:RSA_3DES_EDE_CBC_SHA1:24

In mlmmj's bounce/ dir, the .lastmsg for the bounce has the following  
error from qmail:

> Hi. This is the qmail-send program at server296.com.
> I'm afraid I wasn't able to deliver your message to the following  
> addresses.
> This is a permanent error; I've given up. Sorry it didn't work out.
>
> <editor@comicbookbin.com>:
> The message has too high SPAM probability (2.6)

and this is the bounce stats for that address:

 > /var/spool/mlmmj/topshelf-newsletter-media/bounce$ sudo more editor 
\=comicbookbin.com
2:1158350823 # Fri Sep 15 13:07:03 2006

As always, any help on why this is happening, or where to look for  
troubleshooting is much appreciated.

Thanks,
Nate.

--
Clixel Design & Coding ~ http://clixel.com/

Re: mlmmj-send processes eating cpu

[Morten K. Poulsen]

Hi Nate,

Nate Beaty <natebeaty@gmail.com> wrote:
> Sorry for all the posts.. but I seem to have run into a few problems
> that my feeble troubleshooting skills aren't figuring out.

No problem, that is what the list is for.

> mlmmj-send is still consuming all my CPU resources:

The function that checks SMTP replies was not doing proper EOF checking, so it would enter an infinite loop if the SMTP server closed the connection while mlmmj was waiting for the reply.

I have fixed the issue. Please try the following patch:

http://mlmmj.mmj.dk/~mortenp/patch-mlmmj-1.2.12_RC2-checkwait_smtpreply.diff

Morten

-- 
Morten K. Poulsen <morten@afdelingp.dk>
http://www.afdelingp.dk/

Re: mlmmj-send processes eating cpu

[Nate Beaty]

> he function that checks SMTP replies was not doing proper EOF  
> checking, so it would enter an infinite loop if the SMTP server  
> closed the connection while mlmmj was waiting for the reply.
>
> I have fixed the issue. Please try the following patch:

This seems to have worked. I haven't seen any rampant mlmmj-send  
processes since upgrading to 1.2.12.

Could this by any chance be related to one of the users getting 30+  
copies of the bounce message to an address that he had deactivated  
(I'm not sure what he means by that, but the fact that he's gotten so  
many of these is odd)?

>  -------Original Message-------
>  From: topshelf-newsletter-media+owner@lists.clixel.com
>  Subject: Messages from topshelf-newsletter-media@lists.clixel.com  
> to you have been bouncing
>  Sent: 18 Sep '06 08:00
>
>  Hi, this is the mlmmj program managing the mailinglist
>
>  topshelf-newsletter-media@lists.clixel.com
>
>  Some messages to you could not be delivered. If you're seeing this
>  message it means things are back to normal, and it's merely for your
>  information.
>
>  Here is the list of the bounced messages:
>
>          2

His email was still in bounce/

-rw------- 1 Debian-exim Debian-exim    40 2006-09-15 13:07  
editor=comicbookbin.com
-rw------- 1 Debian-exim Debian-exim 13640 2006-09-15 13:07  
editor=comicbookbin.com.lastmsg

 > /var/spool/mlmmj/topshelf-newsletter-media/bounce$ sudo more editor 
\=comicbookbin.com
2:1158350823 # Fri Sep 15 13:07:03 2006

I don't understand how it lists the 15th as the last message date,  
when clearly his message above says it was sent on the 18th.. ?

Any ideas?

Thanks,
Nate.

(Hoping I can figure out these few errors and let things be again!)

--
Clixel Design & Coding ~ http://clixel.com/

Re: mlmmj-send processes eating cpu

[Morten K. Poulsen]

Hi Nate,

On Mon, 18 Sep 2006 23:58:23 -0700, Nate Beaty <natebeaty@gmail.com> wrote:
>> he function that checks SMTP replies was not doing proper EOF
>> checking, so it would enter an infinite loop if the SMTP server
>> closed the connection while mlmmj was waiting for the reply.
>>
>> I have fixed the issue. Please try the following patch:
> 
> This seems to have worked. I haven't seen any rampant mlmmj-send
> processes since upgrading to 1.2.12.

Ok, good.

> Could this by any chance be related to one of the users getting 30+
> copies of the bounce message to an address that he had deactivated
> (I'm not sure what he means by that, but the fact that he's gotten so
> many of these is odd)?

I don't know. It could be. Perhaps the mail server disconnected after accepting the mail, but mlmmj never got that OK, and therefore re-sent the mail.

Do you have the maillog from the relay host? If you do, could you check whether the mail was sent multiple times from mlmmj to the relay host, or only from the relay host to the end user?

>>  Sent: 18 Sep '06 08:00
[snip]
> His email was still in bounce/
[snip]
> 2:1158350823 # Fri Sep 15 13:07:03 2006
> 
> I don't understand how it lists the 15th as the last message date,
> when clearly his message above says it was sent on the 18th.. ?

Yes, a mail (id and timestamp) is kept in the bounce file for "control/bouncelife" seconds (default is 432000 = 5 days). If the bounce probe ("Messages from $listaddr$ to you have been bouncing") itself does not bounce within this time, the bounce file is removed. Otherwise the user is unsubscribed.

> Any ideas?

If the user still gets multiple copies, please send me a tarball of /var/spool/mlmmj and your maillog.

Morten

-- 
Morten K. Poulsen <morten@afdelingp.dk>
http://www.afdelingp.dk/