Mailman needs 20 seconds to complete per email
![](https://secure.gravatar.com/avatar/4234ab99d7feda0d3aace3c16bb0204d.jpg?s=120&d=mm&r=g)
Hi there,
I'm running an Ubuntu Server 10.04 LTS (Lucid Lynx) with the repository mailman in version
ii mailman 1:2.1.13-1ubuntu0.2 Powerful, web-based mailing list manager
Everything is running fine, so emails arriving at postfix get transfered nearby immediate towards mailman and vice-versa. I'm running Mailman in a multi-domain-MySQL-based setup, as we have to run a lot of different domains in our company. But as said above, this all works.
The problem is, that if Mailman gets an email from Postfix, it sits down and does "something" for roundabout 20 seconds. Then it sends out the emails towards Postfix, and Postfix delivers.
For normal mailing list operation this is not a problem as it sends out one bulk email out to Postfix - but when I do a mass subscription of for example 100 people, Mailman will start to send out the personalized welcome emails one after another - and will also need 20 seconds per email. So it takes 100x 20 seconds = 2000 seconds = 33 minutes till everybody gets his/her welcome email.
Is this usual behaviour of Mailman to do "something" that long? The server is a powerful one with plenty of GHz and RAM. What the hell could this "something" be? :-)
Following you will find my configuration file and the smtp log of mailman:
/etc/mailman/mm_cfg.py:
from Defaults import * MAILMAN_SITE_LIST = 'mailman' DEFAULT_URL_PATTERN = 'http://%s/mailman/' PRIVATE_ARCHIVE_URL = '/mailman/private' IMAGE_LOGOS = '/mailman/images/mailman/' SHORTCUT_ICON = 'favicon.ico' DEFAULT_EMAIL_HOST = 'lists.mycompany.eu' DEFAULT_URL_HOST = 'lists.mycompany.eu' add_virtualhost(DEFAULT_URL_HOST, DEFAULT_EMAIL_HOST) DEFAULT_SERVER_LANGUAGE = 'en' USE_ENVELOPE_SENDER = 0 # Still used? DEFAULT_SEND_REMINDERS = 0 MTA='Postfix' SMTPHOST = 'localhost' SMTPPORT = 10030 POSTFIX_STYLE_VIRTUAL_DOMAINS = ['lists.mycompany.eu', 'lists.myothercompany.org', 'lists.mythirdcompany.eu'] add_virtualhost('lists.myothercompany.org', 'lists.myothercompany.org') add_virtualhost('lists.mythirdcompany.eu', 'lists.mythirdcompany.eu') DEB_LISTMASTER = 'postmaster@mycompany.eu' DEFAULT_ARCHIVE_PRIVATE = 1 MEMBER_PASSWORD_LENGTH = 15 ADMIN_PASSWORD_LENGTH = 20 DEFAULT_LIST_ADVERTISED = No DEFAULT_MAX_NUM_RECIPIENTS = 10 DEFAULT_MAX_MESSAGE_SIZE = 250 # KB DEFAULT_MAX_DAYS_TO_HOLD = 7 DEFAULT_GENERIC_NONMEMBER_ACTION = 2 DEFAULT_SUBSCRIBE_POLICY = 3
/var/log/mailman/smtp
Nov 27 08:00:22 2012 (10393) <mailman.0.1353999601.22399.carbonmarkets@lists.mycompany.eu> smtp to carbonmarkets for 1 recips, completed in 21.021 seconds Nov 27 08:00:43 2012 (10393) <mailman.1.1353999601.22399.agriculture@lists.mycompany.eu> smtp to agriculture for 1 recips, completed in 21.013 seconds Nov 27 08:01:04 2012 (10393) <mailman.2.1353999601.22399.wimix@lists.mycompany.eu> smtp to wimix for 1 recips, completed in 21.007 seconds Nov 27 08:01:25 2012 (10393) <mailman.3.1353999601.22399.out-of-pfalzburger@lists.mycompany.eu> smtp to out-of-pfalzburger for 1 recips, completed in 21.006 seconds Nov 27 08:01:46 2012 (10393) <mailman.4.1353999601.22399.confix@lists.mycompany.eu> smtp to confix for 1 recips, completed in 21.018 seconds Nov 27 08:02:07 2012 (10393) <mailman.5.1353999601.22399.energy@lists.mycompany.eu> smtp to energy for 1 recips, completed in 21.006 seconds Nov 27 08:02:28 2012 (10393) <mailman.6.1353999601.22399.china@lists.mycompany.eu> smtp to china for 1 recips, completed in 21.008 seconds Nov 27 08:02:49 2012 (10393) <mailman.0.1353999601.22399.carbonmarkets@lists.mycompany.eu> smtp to carbonmarkets for 2 recips, completed in 21.007 seconds Nov 27 08:03:10 2012 (10393) <mailman.1.1353999601.22399.agriculture@lists.mycompany.eu> smtp to agriculture for 3 recips, completed in 21.005 seconds Nov 27 08:03:31 2012 (10393) <mailman.2.1353999601.22399.wimix@lists.mycompany.eu> smtp to wimix for 2 recips, completed in 21.007 seconds Nov 27 08:04:13 2012 (10393) <mailman.4.1353999601.22399.confix@lists.mycompany.eu> smtp to confix for 2 recips, completed in 21.011 seconds Nov 27 08:04:34 2012 (10393) <mailman.5.1353999601.22399.energy@lists.mycompany.eu> smtp to energy for 2 recips, completed in 21.007 seconds Nov 27 08:04:55 2012 (10393) <mailman.6.1353999601.22399.china@lists.mycompany.eu> smtp to china for 2 recips, completed in 21.006 seconds Nov 27 09:01:20 2012 (10393) <50B47339.6040405@mycompany.eu> smtp to energy for 61 recips, completed in 21.124 seconds Nov 27 09:18:43 2012 (10393) <50B4774C.1030707@mycompany.eu> smtp to berlinix for 101 recips, completed in 21.126 seconds Nov 27 09:51:29 2012 (10393) <mailman.0.1354006267.31674.china@lists.mycompany.eu> smtp to china for 1 recips, completed in 21.022 seconds Nov 27 10:27:04 2012 (10393) <mailman.0.1354008402.6430.carbonmarkets@lists.mycompany.eu> smtp to carbonmarkets for 1 recips, completed in 21.029 seconds Nov 27 10:27:25 2012 (10393) <mailman.1.1354008402.6430.carbonmarkets@lists.mycompany.eu> smtp to carbonmarkets for 1 recips, completed in 21.004 seconds Nov 27 10:33:09 2012 (10393) <mailman.0.1354008767.9391.energy@lists.mycompany.eu> smtp to energy for 1 recips, completed in 21.022 seconds Nov 27 11:45:19 2012 (10393) <mailman.0.1354013097.25318.confix@lists.mycompany.eu> smtp to confix for 1 recips, completed in 21.023 seconds Nov 27 11:49:32 2012 (10393) <mailman.14.1354013350.10391.confix@lists.mycompany.eu> smtp to confix for 1 recips, completed in 21.018 seconds Nov 27 11:49:54 2012 (10393) <mailman.16.1354013350.10391.confix@lists.mycompany.eu> smtp to confix for 1 recips, completed in 21.815 seconds Nov 27 11:50:18 2012 (10393) <mailman.16.1354013350.10391.confix@lists.mycompany.eu> smtp to confix for 2 recips, completed in 21.391 seconds Nov 27 12:20:17 2012 (10393) <mailman.0.1354015196.1021.confix@lists.mycompany.eu> smtp to confix for 1 recips, completed in 21.015 seconds Nov 27 12:21:05 2012 (10393) <mailman.0.1354015243.1152.wimix@lists.mycompany.eu> smtp to wimix for 1 recips, completed in 21.001 seconds Nov 27 12:40:52 2012 (10393) <50B4A6AD.40705@mycompany.eu> smtp to ecologix for 123 recips, completed in 21.235 seconds
Regards Karsten
![](https://secure.gravatar.com/avatar/56f108518d7ee2544412cc80978e3182.jpg?s=120&d=mm&r=g)
Karsten Becker wrote:
I'm running an Ubuntu Server 10.04 LTS (Lucid Lynx) with the repository mailman in version
ii mailman 1:2.1.13-1ubuntu0.2 Powerful, web-based mailing list manager
Please see the FAQ at <http://wiki.list.org/x/OIDD>.
[...]
/var/log/mailman/smtp
Nov 27 08:00:22 2012 (10393) <mailman.0.1353999601.22399.carbonmarkets@lists.mycompany.eu> smtp to carbonmarkets for 1 recips, completed in 21.021 seconds Nov 27 08:00:43 2012 (10393) <mailman.1.1353999601.22399.agriculture@lists.mycompany.eu> smtp to agriculture for 1 recips, completed in 21.013 seconds [...]
It is extreme and highly unusual for a single Mailman-Postfix SMTP transaction to take 20 seconds, but it is almost certainly due to something in your Postfix configuration.
See the FAQs at <http://wiki.list.org/x/roA9> and <http://wiki.list.org/x/rIA9> for some hints that may help.
Also see the FAQ at <http://wiki.list.org/x/-IA9> for a way to enable logging from Python's smtplib which may help you determine in exactly what part of the SMTP transaction the delay occurs in the response from Postfix.
-- Mark Sapiro <mark@msapiro.net> The highway is for gamblers, San Francisco Bay Area, California better use your sense - B. Dylan
![](https://secure.gravatar.com/avatar/267565c6ab7816fe29beedf9a9cbcd44.jpg?s=120&d=mm&r=g)
- Mark Sapiro <mark@msapiro.net>:
Nov 27 08:00:22 2012 (10393) <mailman.0.1353999601.22399.carbonmarkets@lists.mycompany.eu> smtp to carbonmarkets for 1 recips, completed in 21.021 seconds Nov 27 08:00:43 2012 (10393) <mailman.1.1353999601.22399.agriculture@lists.mycompany.eu> smtp to agriculture for 1 recips, completed in 21.013 seconds [...]
It is extreme and highly unusual for a single Mailman-Postfix SMTP transaction to take 20 seconds, but it is almost certainly due to something in your Postfix configuration.
It's probably some DNS resolution issue (I'd say). Or a really slow smtpd_proxy_filter.
-- Ralf Hildebrandt Charite Universitätsmedizin Berlin ralf.hildebrandt@charite.de Campus Benjamin Franklin http://www.charite.de Hindenburgdamm 30, 12203 Berlin Geschäftsbereich IT, Abt. Netzwerk fon: +49-30-450.570.155
![](https://secure.gravatar.com/avatar/774374b88803523fc821f2577115490a.jpg?s=120&d=mm&r=g)
On Wed, Nov 28, 2012 at 10:56 AM, Ralf Hildebrandt <Ralf.Hildebrandt@charite.de> wrote:
- Mark Sapiro <mark@msapiro.net>:
Nov 27 08:00:22 2012 (10393) <mailman.0.1353999601.22399.carbonmarkets@lists.mycompany.eu> smtp to carbonmarkets for 1 recips, completed in 21.021 seconds Nov 27 08:00:43 2012 (10393) <mailman.1.1353999601.22399.agriculture@lists.mycompany.eu> smtp to agriculture for 1 recips, completed in 21.013 seconds [...]
It is extreme and highly unusual for a single Mailman-Postfix SMTP transaction to take 20 seconds, but it is almost certainly due to something in your Postfix configuration.
It's probably some DNS resolution issue (I'd say). Or a really slow smtpd_proxy_filter.
It could also be a sleep command, in one of the various smtpd_client_restrictions rules. Usually one puts permit_mynetworks (which contains localhost/127.0.0.1) before those though.
-- Ralf Hildebrandt Charite Universitätsmedizin Berlin ralf.hildebrandt@charite.de Campus Benjamin Franklin http://www.charite.de Hindenburgdamm 30, 12203 Berlin Geschäftsbereich IT, Abt. Netzwerk fon: +49-30-450.570.155
Mailman-Users mailing list Mailman-Users@python.org http://mail.python.org/mailman/listinfo/mailman-users Mailman FAQ: http://wiki.list.org/x/AgA3 Security Policy: http://wiki.list.org/x/QIA9 Searchable Archives: http://www.mail-archive.com/mailman-users%40python.org/ Unsubscribe: http://mail.python.org/mailman/options/mailman-users/bcooksley%40kde.org
![](https://secure.gravatar.com/avatar/4234ab99d7feda0d3aace3c16bb0204d.jpg?s=120&d=mm&r=g)
Hi,
thanks for your answers. Maybe I have misunderstood the architecture.
What I can see in the mail.log is, that the incoming email towards a mailing list gets transported nearby "at once" from Postfix to Mailman. Then I see nothing in the Mailman logs for 20 seconds. Then Mailman prints out these message shown below and nearby "at once" I see the email in mail.log going out via Postfix.
So, how/why could a Postfix configuration setting be the cause...? Postfix, as far as I can see it in mail.log, is handling the email fast as hell.
This question is definitely not for ranting - I'm just trying to understand correctly how everything works together to find the "brake"... ;-)
It the meantime I have opened a dedicated port for Mailman at my Postfix for re-injection, without a second unneeded round through Amavis & Co. - but this didn't help either.
Regards Karsten
On 11/27/2012 11:02 PM, Ben Cooksley wrote:
On Wed, Nov 28, 2012 at 10:56 AM, Ralf Hildebrandt <Ralf.Hildebrandt@charite.de> wrote:
- Mark Sapiro <mark@msapiro.net>:
Nov 27 08:00:22 2012 (10393) <mailman.0.1353999601.22399.carbonmarkets@lists.mycompany.eu> smtp to carbonmarkets for 1 recips, completed in 21.021 seconds Nov 27 08:00:43 2012 (10393) <mailman.1.1353999601.22399.agriculture@lists.mycompany.eu> smtp to agriculture for 1 recips, completed in 21.013 seconds [...]
It is extreme and highly unusual for a single Mailman-Postfix SMTP transaction to take 20 seconds, but it is almost certainly due to something in your Postfix configuration.
It's probably some DNS resolution issue (I'd say). Or a really slow smtpd_proxy_filter.
It could also be a sleep command, in one of the various smtpd_client_restrictions rules. Usually one puts permit_mynetworks (which contains localhost/127.0.0.1) before those though.
-- Ralf Hildebrandt Charite Universitätsmedizin Berlin ralf.hildebrandt@charite.de Campus Benjamin Franklin http://www.charite.de Hindenburgdamm 30, 12203 Berlin Geschäftsbereich IT, Abt. Netzwerk fon: +49-30-450.570.155
Mailman-Users mailing list Mailman-Users@python.org http://mail.python.org/mailman/listinfo/mailman-users Mailman FAQ: http://wiki.list.org/x/AgA3 Security Policy: http://wiki.list.org/x/QIA9 Searchable Archives: http://www.mail-archive.com/mailman-users%40python.org/ Unsubscribe: http://mail.python.org/mailman/options/mailman-users/bcooksley%40kde.org
Mailman-Users mailing list Mailman-Users@python.org http://mail.python.org/mailman/listinfo/mailman-users Mailman FAQ: http://wiki.list.org/x/AgA3 Security Policy: http://wiki.list.org/x/QIA9 Searchable Archives: http://www.mail-archive.com/mailman-users%40python.org/ Unsubscribe: http://mail.python.org/mailman/options/mailman-users/karsten.becker%40ecolog...
![](https://secure.gravatar.com/avatar/56f108518d7ee2544412cc80978e3182.jpg?s=120&d=mm&r=g)
Karsten Becker wrote:
What I can see in the mail.log is, that the incoming email towards a mailing list gets transported nearby "at once" from Postfix to Mailman. Then I see nothing in the Mailman logs for 20 seconds. Then Mailman prints out these message shown below and nearby "at once" I see the email in mail.log going out via Postfix.
But if you look at the whole log, you'll see that the connect from Mailman to Postfix to deliver that message occurred 20 seconds earlier.
So, how/why could a Postfix configuration setting be the cause...? Postfix, as far as I can see it in mail.log, is handling the email fast as hell.
Postfix is acknowledging the end of DATA, writing a log entry and delivering the outgoing mail. The whole transaction is:
Connect HELO MAIL FROM RCPT TO ... RCPT TO DATA (message data) .
Somewhere in that transaction, Postfix is taking a long time to respond.
If you need more detailed logging to figure it out, see the last paragraph of my reply at <http://mail.python.org/pipermail/mailman-users/2012-November/074439.html>.
This question is definitely not for ranting - I'm just trying to understand correctly how everything works together to find the "brake"... ;-)
Postfix delivers the mail to Mailman. It is immediately queued in Miailman's in/ queue for IncomingRunner. IncomingRunner wakes up within 1 second and processes the message through the pipeline of Handlers. If there are no errors, nothing is logged. The ToArchive handler queues the message in the archive/ queue for ArchRunner and the ToOutgoing handler queues the message in the out/ queue for OutgoingRunner.
If the message is a post and it is archived, you will see it in the list's archive within 2 seconds (maximum sleep time in IncomingRunner and ArchRunner) of Postfix delivering it to Mailman.
Likewise, within the same 2 seconds, OutgoingRunner will pick up the message and begin processing it. When done, it will write the post and smtp log entries. In the smtp log entries, the 21+ second processing time is the time in OutgoingRunner. All OutgoingRunner is doing is SMTP to the outgoing MTA (host and port set by SMTPHOST, default = 'localhost', and SMTPPORT default = 0, SMTPPORT = 0 implies port 25). It is that SMTP transaction that is taking 21 seconds because of some configuration or other issue in the outgoing MTA.
-- Mark Sapiro <mark@msapiro.net> The highway is for gamblers, San Francisco Bay Area, California better use your sense - B. Dylan
![](https://secure.gravatar.com/avatar/1c4a4096ba25b08fbf1a8cb1c4bf9fcb.jpg?s=120&d=mm&r=g)
On Dec 2, 2012, at 2:27 PM, Mark Sapiro <mark@msapiro.net> wrote:
Likewise, within the same 2 seconds, OutgoingRunner will pick up the message and begin processing it. When done, it will write the post and smtp log entries. In the smtp log entries, the 21+ second processing time is the time in OutgoingRunner. All OutgoingRunner is doing is SMTP to the outgoing MTA (host and port set by SMTPHOST, default = 'localhost', and SMTPPORT default = 0, SMTPPORT = 0 implies port 25). It is that SMTP transaction that is taking 21 seconds because of some configuration or other issue in the outgoing MTA.
A stab in the dark but it sounds like you might have postscreen (part of Postfix) or some other service on port 25 that is causing the delay.
In this day and age, port 25 really should be used only for mail coming from outside destined for your server. I'd suggest creating another incoming Postfix port (e.g. 20025) that is exclusively for mail from Mailman being injected to Postfix. Configure it appropriately so that only lcoalhost or whatever other local hosts need it can use it.
-- Larry Stone lstone19@stonejongleux.com http://www.stonejongleux.com/
![](https://secure.gravatar.com/avatar/cea0cafcc24a090b75d59d6fa86d4d76.jpg?s=120&d=mm&r=g)
Hello Karsten,
- Karsten Becker <karsten.becker@ecologic.eu>:
What I can see in the mail.log is, that the incoming email towards a mailing list gets transported nearby "at once" from Postfix to Mailman. Then I see nothing in the Mailman logs for 20 seconds. Then Mailman prints out these message shown below and nearby "at once" I see the email in mail.log going out via Postfix.
if you want this debugged properly, we will need:
- postconf -n output, as well as master.cf excerpts of the smtpd services you access
- postfix logs from a posting that get's delayed, if possible, delivery "from outside" to mailman and from mailman back to postfix
- the corresponding mailman log
All logs should contain the timestamps. Without full logs there is no way we can help you solve this.
Cheers Stefan
![](https://secure.gravatar.com/avatar/267565c6ab7816fe29beedf9a9cbcd44.jpg?s=120&d=mm&r=g)
- Stefan Foerster <cite@incertum.net>:
Hello Karsten,
- Karsten Becker <karsten.becker@ecologic.eu>:
What I can see in the mail.log is, that the incoming email towards a mailing list gets transported nearby "at once" from Postfix to Mailman. Then I see nothing in the Mailman logs for 20 seconds. Then Mailman prints out these message shown below and nearby "at once" I see the email in mail.log going out via Postfix.
if you want this debugged properly, we will need:
- postconf -n output, as well as master.cf excerpts of the smtpd services you access
- postfix logs from a posting that get's delayed, if possible, delivery "from outside" to mailman and from mailman back to postfix
- the corresponding mailman log
Exactly.
-- Ralf Hildebrandt Charite Universitätsmedizin Berlin ralf.hildebrandt@charite.de Campus Benjamin Franklin http://www.charite.de Hindenburgdamm 30, 12203 Berlin Geschäftsbereich IT, Abt. Netzwerk fon: +49-30-450.570.155
![](https://secure.gravatar.com/avatar/4234ab99d7feda0d3aace3c16bb0204d.jpg?s=120&d=mm&r=g)
On 12/03/2012 07:16 AM, Stefan Foerster wrote:
- postconf -n output, as well as master.cf excerpts of the smtpd services you access
- postfix logs from a posting that get's delayed, if possible, delivery "from outside" to mailman and from mailman back to postfix
- the corresponding mailman log
Here we go, find the files attached.
Just inform me if something is missing...
If Ralf is wondering that he thinks he knows that kind of setup - the whole mailing stuff got set up using his book... :-)
Regards Karsten
![](https://secure.gravatar.com/avatar/1c4a4096ba25b08fbf1a8cb1c4bf9fcb.jpg?s=120&d=mm&r=g)
Missing the most important thing which is a Postfix log.
-- Larry Stone lstone19@stonejongleux.com http://www.stonejongleux.com/
On Dec 3, 2012, at 3:27 AM, Karsten Becker <karsten.becker@ecologic.eu> wrote:
On 12/03/2012 07:16 AM, Stefan Foerster wrote:
- postconf -n output, as well as master.cf excerpts of the smtpd services you access
- postfix logs from a posting that get's delayed, if possible, delivery "from outside" to mailman and from mailman back to postfix
- the corresponding mailman log
Here we go, find the files attached.
Just inform me if something is missing...
If Ralf is wondering that he thinks he knows that kind of setup - the whole mailing stuff got set up using his book... :-)
Regards Karsten <master.cf><post.txt><postconf.conf><smtp.txt>------------------------------------------------------ Mailman-Users mailing list Mailman-Users@python.org http://mail.python.org/mailman/listinfo/mailman-users Mailman FAQ: http://wiki.list.org/x/AgA3 Security Policy: http://wiki.list.org/x/QIA9 Searchable Archives: http://www.mail-archive.com/mailman-users%40python.org/ Unsubscribe: http://mail.python.org/mailman/options/mailman-users/lstone19%40stonejongleu...
![](https://secure.gravatar.com/avatar/4234ab99d7feda0d3aace3c16bb0204d.jpg?s=120&d=mm&r=g)
Oh, seems like it is getting cut... okay, here it is pasted directly into the email:
Dec 3 09:52:39 mail01 postfix/smtpd[15196]: connect from fw01.ecodmz.local[80.149.253.142] Dec 3 09:52:39 mail01 postfix/smtpd[15196]: 8BA32172007D: client=fw01.ecodmz.local[80.149.253.142], sasl_method=PLAIN, sasl_username=karsten.becker@foo.de Dec 3 09:52:39 mail01 postfix/cleanup[15129]: 8BA32172007D: message-id=<50BC6857.6000204@foo.de> Dec 3 09:52:39 mail01 postfix/qmgr[15109]: 8BA32172007D: from=<karsten.becker@foo.de>, size=985, nrcpt=1 (queue active) Dec 3 09:52:39 mail01 postfix/smtpd[15196]: disconnect from fw01.ecodmz.local[80.149.253.142] Dec 3 09:52:39 mail01 amavis[23946]: (23946-06) ESMTP::10027 /var/lib/amavis/tmp/amavis-20121203T082655-23946: <karsten.becker@foo.de> -> <karsten-test@lists.foo.de> Received: SIZE=985 from mail01.ecodmz.local ([127.0.0.1]) by localhost (mail01.ecodmz.local [127.0.0.1]) (amavisd-maia, port 10027) with ESMTP id 23946-06 for <karsten-test@lists.foo.de>; Mon, 3 Dec 2012 09:52:39 +0100 (CET) Dec 3 09:52:39 mail01 amavis[23946]: (23946-06) Checking: BYPASS_LAN [80.149.253.142] <karsten.becker@foo.de> -> <karsten-test@lists.foo.de> Dec 3 09:52:39 mail01 amavis[23946]: (23946-06) FWD via SMTP: [127.0.0.1]:10025 <karsten.becker@foo.de> -> <karsten-test@lists.foo.de> Dec 3 09:52:39 mail01 postfix/smtpd[15139]: connect from localhost[127.0.0.1] Dec 3 09:52:39 mail01 postfix/smtpd[15139]: B0E971720080: client=fw01.ecodmz.local[80.149.253.142] Dec 3 09:52:39 mail01 postfix/cleanup[15140]: B0E971720080: message-id=<50BC6857.6000204@foo.de> Dec 3 09:52:39 mail01 postfix/qmgr[15109]: B0E971720080: from=<karsten.becker@foo.de>, size=1463, nrcpt=1 (queue active) Dec 3 09:52:39 mail01 postfix/smtpd[15139]: disconnect from localhost[127.0.0.1] Dec 3 09:52:39 mail01 postfix/smtp[15137]: 8BA32172007D: to=<karsten-test@lists.foo.de>, relay=127.0.0.1[127.0.0.1]:10027, delay=0.23, delays=0.08/0/0/0.14, dsn=2.6.0, status=sent (250 2.6.0 Ok, id=23946-06, from MTA: 250 2.0.0 Ok: queued as B0E971720080) Dec 3 09:52:39 mail01 postfix/qmgr[15109]: 8BA32172007D: removed Dec 3 09:52:39 mail01 amavis[23946]: (23946-06) extra modules loaded: /usr/lib/perl5/auto/NetAddr/IP/Util/inet_n2dx.al, /usr/lib/perl5/auto/NetAddr/IP/Util/ipv6_n2d.al, /usr/lib/perl5/auto/NetAddr/IP/Util/ipv6_n2x.al, Error.pm, Mail/DKIM/Algorithm/Base.pm, Mail/DKIM/Algorithm/dk_rsa_sha1.pm, Mail/DKIM/Algorithm/rsa_sha1.pm, Mail/DKIM/Algorithm/rsa_sha256.pm, Mail/DKIM/AuthorDomainPolicy.pm, Mail/DKIM/Canonicalization/Base.pm, Mail/DKIM/Canonicalization/DkCommon.pm, Mail/DKIM/Canonicalization/DkimCommon.pm, Mail/DKIM/Canonicalization/dk_nofws.pm, Mail/DKIM/Canonicalization/dk_simple.pm, Mail/DKIM/Canonicalization/nowsp.pm, Mail/DKIM/Canonicalization/relaxed.pm, Mail/DKIM/Canonicalization/simple.pm, Mail/DKIM/Common.pm, Mail/DKIM/DNS.pm, Mail/DKIM/DkPolicy.pm, Mail/DKIM/DkSignature.pm, Mail/DKIM/DkimPolicy.pm, Mail/DKIM/Key.pm, Mail/DKIM/KeyValueList.pm, Mail/DKIM/MessageParser.pm, Mail/DKIM/Policy.pm, Mail/DKIM/PublicKey.pm, Mail/DKIM/Signature.pm, Mail/DKIM/Verifier.pm, Ma il/SPF.pm , Mail/SPF/Base.pm...
Dec 3 09:52:39 mail01 amavis[23946]: (23946-06) ..., Mail/SPF/Exception.pm, Mail/SPF/MacroString.pm, Mail/SPF/Record.pm, Mail/SPF/Request.pm, Mail/SPF/Result.pm, Mail/SPF/Server.pm, Mail/SPF/Util.pm, Mail/SpamAssassin/Bayes/CombineChi.pm, Mail/SpamAssassin/Locales.pm, Mail/SpamAssassin/Plugin/Bayes.pm, Mail/SpamAssassin/Plugin/BodyEval.pm, Mail/SpamAssassin/Plugin/Check.pm, Mail/SpamAssassin/Plugin/DKIM.pm, Mail/SpamAssassin/Plugin/DNSEval.pm, Mail/SpamAssassin/Plugin/FreeMail.pm, Mail/SpamAssassin/Plugin/HTMLEval.pm, Mail/SpamAssassin/Plugin/HTTPSMismatch.pm, Mail/SpamAssassin/Plugin/HeaderEval.pm, Mail/SpamAssassin/Plugin/ImageInfo.pm, Mail/SpamAssassin/Plugin/MIMEEval.pm, Mail/SpamAssassin/Plugin/RelayEval.pm, Mail/SpamAssassin/Plugin/URIDetail.pm, Mail/SpamAssassin/Plugin/URIEval.pm, Mail/SpamAssassin/Plugin/VBounce.pm, Mail/SpamAssassin/Plugin/WLBLEval.pm, unicore/lib/gc_sc/Word.pl, version.pm
Dec 3 09:52:39 mail01 dovecot: imap(karsten.becker.intern@foo.de): Disconnected: Disconnected in IDLE in=14712 out=131057
Dec 3 09:52:39 mail01 postfix/pipe[15199]: B0E971720080: to=<karsten-test@lists.foo.de>, relay=mailman, delay=0.21, delays=0.05/0.01/0/0.16, dsn=2.0.0, status=sent (delivered via mailman service)
Dec 3 09:53:02 mail01 postfix/smtpd[15221]: 0D45F172007D: client=localhost[127.0.0.1]
Dec 3 09:53:02 mail01 postfix/cleanup[15140]: 0D45F172007D: message-id=<50BC6857.6000204@foo.de>
Dec 3 09:53:02 mail01 postfix/qmgr[15109]: 0D45F172007D: from=<karsten-test-bounces@lists.foo.de>, size=2526, nrcpt=2 (queue active)
Dec 3 09:53:02 mail01 postfix/smtpd[15221]: 0F2D51720080: client=localhost[127.0.0.1]
Dec 3 09:53:02 mail01 postfix/cleanup[15140]: 0F2D51720080: message-id=<50BC6857.6000204@foo.de>
Dec 3 09:53:02 mail01 postfix/qmgr[15109]: 0F2D51720080: from=<karsten-test-bounces@lists.foo.de>, size=2556, nrcpt=1 (queue active)
Dec 3 09:53:02 mail01 postfix/smtpd[15221]: 109CC1720081: client=localhost[127.0.0.1]
Dec 3 09:53:02 mail01 postfix/cleanup[15140]: 109CC1720081: message-id=<50BC6857.6000204@foo.de> Dec 3 09:53:02 mail01 postfix/qmgr[15109]: 109CC1720081: from=<karsten-test-bounces@lists.foo.de>, size=2526, nrcpt=6 (queue active) Dec 3 09:53:02 mail01 postfix/smtpd[15221]: disconnect from localhost[127.0.0.1] Dec 3 09:53:02 mail01 dovecot: lda(toni.testa@bar.us): sieve: msgid=<50BC6857.6000204@foo.de>: stored mail into mailbox 'INBOX' Dec 3 09:53:02 mail01 postfix/pipe[15222]: 0D45F172007D: to=<toni.testa@bar.us>, relay=dovecot, delay=0.1, delays=0.01/0.01/0/0.09, dsn=2.0.0, status=sent (delivered via dovecot service) Dec 3 09:53:02 mail01 postfix/smtp[15141]: 0D45F172007D: to=<erna.testa@gmx.net>, relay=mx01.foo.de[85.214.42.230]:25, delay=0.21, delays=0.01/0/0.02/0.19, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 2164B7408D) Dec 3 09:53:02 mail01 postfix/smtp[15223]: 0F2D51720080: to=<erna.testa2@gmail.com>, relay=mx01.foo.de[85.214.42.230]:25, delay=0.2, delays=0/0.01/0.05/0.15, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 23C087408E) Dec 3 09:53:02 mail01 postfix/qmgr[15109]: 0D45F172007D: removed Dec 3 09:53:02 mail01 postfix/qmgr[15109]: 0F2D51720080: removed Dec 3 09:53:02 mail01 postfix/smtp[15225]: 109CC1720081: to=<bernhard.glomm.intern@foo.de>, relay=mx01.foo.de[85.214.42.230]:25, delay=0.23, delays=0.01/0.01/0.06/0.16, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 275797408F) Dec 3 09:53:02 mail01 postfix/smtp[15225]: 109CC1720081: to=<bernhard.glomm@foo.de>, relay=mx01.foo.de[85.214.42.230]:25, delay=0.23, delays=0.01/0.01/0.06/0.16, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 275797408F) Dec 3 09:53:02 mail01 postfix/smtp[15225]: 109CC1720081: to=<frank.rudek@foo.de>, relay=mx01.foo.de[85.214.42.230]:25, delay=0.23, delays=0.01/0.01/0.06/0.16, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 275797408F) Dec 3 09:53:02 mail01 postfix/smtp[15225]: 109CC1720081: to=<karsten.becker@foo.de>, relay=mx01.foo.de[85.214.42.230]:25, delay=0.23, delays=0.01/0.01/0.06/0.16, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 275797408F) Dec 3 09:53:02 mail01 postfix/smtp[15225]: 109CC1720081: to=<b.glomm@gmx.de>, relay=mx01.foo.de[85.214.42.230]:25, delay=0.23, delays=0.01/0.01/0.06/0.16, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 275797408F) Dec 3 09:53:02 mail01 postfix/smtp[15225]: 109CC1720081: to=<karstenrbecker@gmx.de>, relay=mx01.foo.de[85.214.42.230]:25, delay=0.23, delays=0.01/0.01/0.06/0.16, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 275797408F) Dec 3 09:53:02 mail01 postfix/qmgr[15109]: 109CC1720081: removed
![](https://secure.gravatar.com/avatar/1c4a4096ba25b08fbf1a8cb1c4bf9fcb.jpg?s=120&d=mm&r=g)
A few comments below on selected lines:
On Mon, 3 Dec 2012, Karsten Becker wrote:
Dec 3 09:52:39 mail01 postfix/pipe[15199]: B0E971720080: to=<karsten-test@lists.foo.de>, relay=mailman, delay=0.21, delays=0.05/0.01/0/0.16, dsn=2.0.0, status=sent (delivered via mailman service)
As I now see in your master.cf, you're using the postfix-to-mailman.py script. This is a third-party product and is not supported by the Mailman developers. I know nothing about postfix-to-mailman so I have no idea if that's the source of the delay.
Dec 3 09:53:02 mail01 postfix/smtpd[15221]: 0D45F172007D: client=localhost[127.0.0.1]
OK, now it's 23 seconds later but we're missing the "connect from" log line from Postfix. At this point, Postfix already has the message as evidenced by the queue-ID (0D45F172007D) in the message. So without seeing when the connect occurred, we don't know if the delay is in Mailman or Postfix.
-- Larry Stone lstone19@stonejongleux.com
![](https://secure.gravatar.com/avatar/4234ab99d7feda0d3aace3c16bb0204d.jpg?s=120&d=mm&r=g)
On 12/03/2012 05:35 PM, Larry Stone wrote:
Dec 3 09:53:02 mail01 postfix/smtpd[15221]: 0D45F172007D: client=localhost[127.0.0.1]
OK, now it's 23 seconds later but we're missing the "connect from" log line from Postfix. At this point, Postfix already has the message as evidenced by the queue-ID (0D45F172007D) in the message. So without seeing when the connect occurred, we don't know if the delay is in Mailman or Postfix.
That should help:
Dec 3 09:53:02 mail01 postfix/smtpd[15221]: connect from localhost[127.0.0.1] Dec 3 09:53:02 mail01 postfix/smtpd[15221]: 0D45F172007D: client=localhost[127.0.0.1]
Seems like I need to take a closer look at the postfix-to-mailman.py...
Regards Karsten
![](https://secure.gravatar.com/avatar/56f108518d7ee2544412cc80978e3182.jpg?s=120&d=mm&r=g)
Karsten Becker <karsten.becker@ecologic.eu> wrote:
Seems like I need to take a closer look at the postfix-to-mailman.py...
I may have more after I return to a real MUA, but postfix_to_mailman.py is NOT the problem. It only does delivery TO Mailman. Your issue is with outgoing mail from Mailman.
-- Mark Sapiro <mark@msapiro.net> Sent from my Android phone with K-9 Mail. Please excuse my brevity.
![](https://secure.gravatar.com/avatar/56f108518d7ee2544412cc80978e3182.jpg?s=120&d=mm&r=g)
On 12/3/2012 8:35 AM, Larry Stone wrote:
A few comments below on selected lines:
On Mon, 3 Dec 2012, Karsten Becker wrote:
Dec 3 09:52:39 mail01 postfix/pipe[15199]: B0E971720080: to=<karsten-test@lists.foo.de>, relay=mailman, delay=0.21, delays=0.05/0.01/0/0.16, dsn=2.0.0, status=sent (delivered via mailman service)
As I now see in your master.cf, you're using the postfix-to-mailman.py script. This is a third-party product and is not supported by the Mailman developers. I know nothing about postfix-to-mailman so I have no idea if that's the source of the delay.
As I said in my reply earlier, the issue has nothing to do with postfix_to_mailman.py. This module only delivers mail to Mailman. We know Mailman got the mail without delay because 1) Postfix is telling us that above, and 2) from the smtp log, OutgoingRunner got the outgoing message 21.038 seconds before 09:53:02, i.e. at 9:52:40 or :41, just 1 or two seconds after postfix_to_mailman.py delivered it to Mailman's in/ queue.
Dec 3 09:53:02 mail01 postfix/smtpd[15221]: 0D45F172007D: client=localhost[127.0.0.1]
OK, now it's 23 seconds later but we're missing the "connect from" log line from Postfix. At this point, Postfix already has the message as evidenced by the queue-ID (0D45F172007D) in the message. So without seeing when the connect occurred, we don't know if the delay is in Mailman or Postfix.
Exactly, but I clain the delay is in the SMTP interaction between OutgoingRunner and Postfix. To narrow it down, pleas do what I suggested twice before. See the FAQ at <http://wiki.list.org/x/-IA9>. Add the
self.__conn.set_debuglevel(1)
in the definition of __connect in Mailman/Handlers/SPTPDirect.py, restart Mailman, send a post and then look at Mailman's error log which should log with timestamps each step of the SMTP transaction.
That will tell you where the delay is more precisely that Postfix's log.
As to why there is a delay, I am not a real Postfix expert, I just pretend, so I'm not going to look at your postconf -n output until you do the above and report what you find.
-- Mark Sapiro <mark@msapiro.net> The highway is for gamblers, San Francisco Bay Area, California better use your sense - B. Dylan
![](https://secure.gravatar.com/avatar/1c4a4096ba25b08fbf1a8cb1c4bf9fcb.jpg?s=120&d=mm&r=g)
On Dec 3, 2012, at 9:22 PM, Mark Sapiro <mark@msapiro.net> wrote:
Dec 3 09:53:02 mail01 postfix/smtpd[15221]: 0D45F172007D: client=localhost[127.0.0.1]
OK, now it's 23 seconds later but we're missing the "connect from" log line from Postfix. At this point, Postfix already has the message as evidenced by the queue-ID (0D45F172007D) in the message. So without seeing when the connect occurred, we don't know if the delay is in Mailman or Postfix.
Exactly, but I clain the delay is in the SMTP interaction between OutgoingRunner and Postfix.
Karsten did send the additional log line showing the connect did not happen until 9:53:02.
Maybe something is happening that is delaying Postfix in creating the SMTPD process. Maybe a slow DNS response (resolving 127.0.0.1 to localhost)? I'm not sure when Postfix would log the connect message in that case but since it logs the resolved hostname, I'm thinking at the end.
-- Larry Stone lstone19@stonejongleux.com http://www.stonejongleux.com/
![](https://secure.gravatar.com/avatar/56f108518d7ee2544412cc80978e3182.jpg?s=120&d=mm&r=g)
Larry Stone wrote:
On Dec 3, 2012, at 9:22 PM, Mark Sapiro <mark@msapiro.net> wrote:
Exactly, but I clain the delay is in the SMTP interaction between OutgoingRunner and Postfix.
Karsten did send the additional log line showing the connect did not happen until 9:53:02.
I still want to see the smtplib debug output. That will show exactly where the delay is and allow focus on exactly that step in the SMTP transaction.
-- Mark Sapiro <mark@msapiro.net> The highway is for gamblers, San Francisco Bay Area, California better use your sense - B. Dylan
![](https://secure.gravatar.com/avatar/4234ab99d7feda0d3aace3c16bb0204d.jpg?s=120&d=mm&r=g)
WTF?
Dec 04 09:25:15 2012 qrunner(8680): connect: ('localhost', 10030) Dec 04 09:25:15 2012 qrunner(8680): connect: (10030, 'localhost') Dec 04 09:25:36 2012 qrunner(8680): reply: '220 mail01.foodmz.local ESMTP Ecologic Institute ready\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: retcode (220); Msg: mail01.foodmz.local ESMTP Foo ready Dec 04 09:25:36 2012 qrunner(8680): connect: mail01.foodmz.local ESMTP Foo ready Dec 04 09:25:36 2012 qrunner(8680): send: 'ehlo mail01.foodmz.local\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-mail01.foodmz.local\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-PIPELINING\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-SIZE 20971520\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-ETRN\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-STARTTLS\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-AUTH PLAIN LOGIN\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-AUTH=PLAIN LOGIN\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-XFORWARD NAME ADDR PROTO HELO SOURCE PORT\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-ENHANCEDSTATUSCODES\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-8BITMIME\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250 DSN\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: retcode (250); Msg: mail01.foodmz.local
What is this f***ing Postfix doing...????
Or is it the mailman searching for localhost all the time? But "localhost" has an entry in /etc/hosts and /etc/nsswitch.conf looks okay.
Regards Karsten
On 12/04/2012 07:03 AM, Mark Sapiro wrote:
Larry Stone wrote:
On Dec 3, 2012, at 9:22 PM, Mark Sapiro <mark@msapiro.net> wrote:
Exactly, but I clain the delay is in the SMTP interaction between OutgoingRunner and Postfix.
Karsten did send the additional log line showing the connect did not happen until 9:53:02.
I still want to see the smtplib debug output. That will show exactly where the delay is and allow focus on exactly that step in the SMTP transaction.
![](https://secure.gravatar.com/avatar/334b870d5b26878a79b2dc4cfcc500bc.jpg?s=120&d=mm&r=g)
Karsten Becker writes:
WTF?
Dec 04 09:25:15 2012 qrunner(8680): connect: ('localhost', 10030) Dec 04 09:25:15 2012 qrunner(8680): connect: (10030, 'localhost') Dec 04 09:25:36 2012 qrunner(8680): reply: '220 mail01.foodmz.local ESMTP Ecologic Institute ready\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: retcode (220); Msg: mail01.foodmz.local ESMTP Foo ready Dec 04 09:25:36 2012 qrunner(8680): connect: mail01.foodmz.local ESMTP Foo ready Dec 04 09:25:36 2012 qrunner(8680): send: 'ehlo mail01.foodmz.local\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-mail01.foodmz.local\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-PIPELINING\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-SIZE 20971520\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-ETRN\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-STARTTLS\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-AUTH PLAIN LOGIN\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-AUTH=PLAIN LOGIN\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-XFORWARD NAME ADDR PROTO HELO SOURCE PORT\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-ENHANCEDSTATUSCODES\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-8BITMIME\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250 DSN\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: retcode (250); Msg: mail01.foodmz.local
What is this f***ing Postfix doing...????
This is just a normal handshake. The two connects at 09:25:15 are evidently a low-level TCP handshake by the qrunner connecting to the SMTP server (Postfix, and port 25 is implied) on localhost from port 10030 (localhost is implied for the "from" host). Why it's listed twice I don't know; perhaps the first one is the qrunner sending an initial SYN packet, and the second is the qrunner receiving an ACK that confirms the connection is established.
The first two replies at 09:25:36 are not really replies: they are Postfix announcing its presence to the new connection, not a response to anything the qrunner said. I have no idea why it takes 21 seconds for Postfix to make that announcement.
I would guess that the following connect is the qrunner logging the successful connection, not a new one. The send, starting with "elho", is the qrunner identifying itself to Postfix. Each line starting with "250" is a status code (250) saying Postfix is happy to talk to "mail01.foodmz.local", followed by an extended SMTP feature that Postfix offers over and above the features required by RFC 821 (and its successors). The final "reply: retcode" is the qrunner's interpretation of the preceding gobbledygook, that Postfix is ready to talk, and accept a message from "mail01".
HTH
Steve
![](https://secure.gravatar.com/avatar/267565c6ab7816fe29beedf9a9cbcd44.jpg?s=120&d=mm&r=g)
- Stephen J. Turnbull <stephen@xemacs.org>:
Karsten Becker writes:
WTF?
Dec 04 09:25:15 2012 qrunner(8680): connect: ('localhost', 10030) Dec 04 09:25:15 2012 qrunner(8680): connect: (10030, 'localhost') Dec 04 09:25:36 2012 qrunner(8680): reply: '220 mail01.foodmz.local ESMTP Ecologic Institute ready\r\n'
Postfix presents it's banner 20 seconds after the connection has been established.
Things to try:
- disable chroot for THAT smtpd on port 10030
- check that you have enough instances of that particular smtpd (otherwise mailman must wait until one is available)
- check the restrictions for that particular smtpd
-- Ralf Hildebrandt Charite Universitätsmedizin Berlin ralf.hildebrandt@charite.de Campus Benjamin Franklin http://www.charite.de Hindenburgdamm 30, 12203 Berlin Geschäftsbereich IT, Abt. Netzwerk fon: +49-30-450.570.155
![](https://secure.gravatar.com/avatar/267565c6ab7816fe29beedf9a9cbcd44.jpg?s=120&d=mm&r=g)
- Ralf Hildebrandt <Ralf.Hildebrandt@charite.de>:
- Stephen J. Turnbull <stephen@xemacs.org>:
Karsten Becker writes:
WTF?
Dec 04 09:25:15 2012 qrunner(8680): connect: ('localhost', 10030) Dec 04 09:25:15 2012 qrunner(8680): connect: (10030, 'localhost') Dec 04 09:25:36 2012 qrunner(8680): reply: '220 mail01.foodmz.local ESMTP Ecologic Institute ready\r\n'
Postfix presents it's banner 20 seconds after the connection has been established.
Things to try:
- disable chroot for THAT smtpd on port 10030
- check that you have enough instances of that particular smtpd (otherwise mailman must wait until one is available)
- check the restrictions for that particular smtpd
- try connecting manually!
-- Ralf Hildebrandt Charite Universitätsmedizin Berlin ralf.hildebrandt@charite.de Campus Benjamin Franklin http://www.charite.de Hindenburgdamm 30, 12203 Berlin Geschäftsbereich IT, Abt. Netzwerk fon: +49-30-450.570.155
![](https://secure.gravatar.com/avatar/4234ab99d7feda0d3aace3c16bb0204d.jpg?s=120&d=mm&r=g)
On 12/04/2012 03:15 PM, Ralf Hildebrandt wrote:
Postfix presents it's banner 20 seconds after the connection has been established.
Things to try:
- disable chroot for THAT smtpd on port 10030
- check that you have enough instances of that particular smtpd (otherwise mailman must wait until one is available)
- check the restrictions for that particular smtpd
- try connecting manually!
No, chroot, default number of processes (= 100, far away from that), no restrictions...
127.0.0.1:10030 inet n - - - - smtpd -o smtpd_authorized_xforward_hosts=127.0.0.0/8 -o content_filter= -o local_recipient_maps= -o relay_recipient_maps= -o disable_dns_lookups=yes -o smtpd_restriction_classes= -o smtpd_delay_reject=no -o smtpd_client_restrictions=permit_mynetworks,reject -o smtpd_helo_restrictions= -o smtpd_sender_restrictions= -o smtpd_recipient_restrictions=permit_mynetworks,reject -o smtpd_data_restrictions=reject_unauth_pipelining -o smtpd_end_of_data_restrictions= -o mynetworks=127.0.0.0/8 -o smtpd_error_sleep_time=0 -o smtpd_soft_error_limit=1001 -o smtpd_hard_error_limit=1000 -o smtpd_client_connection_count_limit=0 -o smtpd_client_connection_rate_limit=0 -o receive_override_options=no_header_body_checks,no_unknown_recipient_checks
But... damned - I got it:
root@mail01.foodmz.local:/var/log/mailman# telnet localhost 10030 Trying ::1... Trying 127.0.0.1... Connected to localhost. Escape character is '^]'. 220 mail01.foodmz.local ESMTP Foo ready
The machine is IPv6 capable, but Postfix is listening to IPv4. As Mailman is configured in mm_cfg.py to use "localhost" for injecting back, it gets back "::1" first, tries to connect for 20s, and then falls back to IPv4, which then succeeds.
So I simply added in my /etc/hosts an entry called localhost-ipv4 for 127.0.0.1 and took that for SMTPHOST in mm_cfg.py.
And, what should I say... like a rocket!
Thanks a lot to all of you for assisting me!!!!
Regards from Berlin/Germany Karsten
![](https://secure.gravatar.com/avatar/267565c6ab7816fe29beedf9a9cbcd44.jpg?s=120&d=mm&r=g)
- Karsten Becker <karsten.becker@ecologic.eu>:
No, chroot, default number of processes (= 100, far away from that), no restrictions...
127.0.0.1:10030 inet n - - - - smtpd
This one IS chrooted...
root@mail01.foodmz.local:/var/log/mailman# telnet localhost 10030 Trying ::1... Trying 127.0.0.1... Connected to localhost. Escape character is '^]'. 220 mail01.foodmz.local ESMTP Foo ready
The machine is IPv6 capable, but Postfix is listening to IPv4. As Mailman is configured in mm_cfg.py to use "localhost" for injecting back, it gets back "::1" first, tries to connect for 20s, and then falls back to IPv4, which then succeeds.
AAAAAH!
So I simply added in my /etc/hosts an entry called localhost-ipv4 for 127.0.0.1 and took that for SMTPHOST in mm_cfg.py.
And, what should I say... like a rocket!
Thanks a lot to all of you for assisting me!!!!
-- Ralf Hildebrandt Charite Universitätsmedizin Berlin ralf.hildebrandt@charite.de Campus Benjamin Franklin http://www.charite.de Hindenburgdamm 30, 12203 Berlin Geschäftsbereich IT, Abt. Netzwerk fon: +49-30-450.570.155
![](https://secure.gravatar.com/avatar/56f108518d7ee2544412cc80978e3182.jpg?s=120&d=mm&r=g)
Karsten Becker wrote:
Dec 04 09:25:15 2012 qrunner(8680): connect: ('localhost', 10030)
smtplib begins the connect process at 09:25:15
Dec 04 09:25:15 2012 qrunner(8680): connect: (10030, 'localhost')
at 09:25:15 smtplib has established a socket (connection) to port 10030 on localhost. This message indicates the connect was successful and the socket exists.
Dec 04 09:25:36 2012 qrunner(8680): reply: '220 mail01.foodmz.local ESMTP Ecologic Institute ready\r\n'
Postfix answers the connect with the above 220 status message at 09:25:36 (21 seconds later). Mailman has been doing nothing but waiting for this reply from Postfix.
Dec 04 09:25:36 2012 qrunner(8680): reply: retcode (220); Msg: mail01.foodmz.local ESMTP Foo ready
smtplib.getreply() returns the retcode and message to smtplib.connect().
Dec 04 09:25:36 2012 qrunner(8680): connect: mail01.foodmz.local ESMTP Foo ready
smtplib.connect() logs its return to the caller (in this case, smtplib.sendmail()). The connection is established.
Dec 04 09:25:36 2012 qrunner(8680): send: 'ehlo mail01.foodmz.local\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-mail01.foodmz.local\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-PIPELINING\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-SIZE 20971520\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-ETRN\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-STARTTLS\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-AUTH PLAIN LOGIN\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-AUTH=PLAIN LOGIN\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-XFORWARD NAME ADDR PROTO HELO SOURCE PORT\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-ENHANCEDSTATUSCODES\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250-8BITMIME\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: '250 DSN\r\n' Dec 04 09:25:36 2012 qrunner(8680): reply: retcode (250); Msg: mail01.foodmz.local
smtplib.sendmail() continues with EHLO and gets a reply.
What is this f***ing Postfix doing...????
It is waiting 21 seconds to answer the connect. What it's doing and why during that time is a Postfix question, not a Mailman question.
Or is it the mailman searching for localhost all the time? But "localhost" has an entry in /etc/hosts and /etc/nsswitch.conf looks okay.
It is not Mailman. Mailman has established the socket and is waiting for Postfix to speak. It's Postfix's turn.
What happens if you
telnet localhost 10030
Presumably, it takes 21 seconds before you get a response from Postfix. That's the delay.
I wrote the above before realizing that others had replied and the issue was resolved. I'm posting it anyway just for the detailed interpretation of the smtplib debug messages.
-- Mark Sapiro <mark@msapiro.net> The highway is for gamblers, San Francisco Bay Area, California better use your sense - B. Dylan
![](https://secure.gravatar.com/avatar/4234ab99d7feda0d3aace3c16bb0204d.jpg?s=120&d=mm&r=g)
On 12/04/2012 07:39 PM, Mark Sapiro wrote:
I wrote the above before realizing that others had replied and the issue was resolved. I'm posting it anyway just for the detailed interpretation of the smtplib debug messages.
Thanks a lot anyway!
Regards Karsten
-- Karsten Becker Head of Information Technology
Ecologic Institute Berlin - Brussels - Vienna - Washington DC
Pfalzburger Strasse 43/44 | 10717 Berlin | Germany Tel. +49 (30) 86880-137 | Fax +49 (30) 86880-100 http://www.ecologic.eu/ | http://www.ecologic-events.eu/
Ecologic Institute publishes a monthly newsletter. To subscribe, please register at: http://www.ecologic.eu/subscribe.htm
Ecologic Institut gemeinnuetzige GmbH GF/Director: R. Andreas Kraemer | AG Charlottenburg HRB 57947 | USt/VAT-IdNr. DE811963464 'Ecologic' is a Trade Mark (TM) of Ecologic Institut gemeinnuetzige GmbH, Berlin.
![](https://secure.gravatar.com/avatar/56f108518d7ee2544412cc80978e3182.jpg?s=120&d=mm&r=g)
Karsten Becker wrote:
Oh, seems like it is getting cut... okay, here it is pasted directly into the email:
Apparently your MUA is giving the mail log attachment a MIME type other than text/plain which is a bit surprising as it did give the other 4 files text/plain Content-Type:
-- Mark Sapiro <mark@msapiro.net> The highway is for gamblers, San Francisco Bay Area, California better use your sense - B. Dylan
participants (7)
-
Ben Cooksley
-
Karsten Becker
-
Larry Stone
-
Mark Sapiro
-
Ralf Hildebrandt
-
Stefan Foerster
-
Stephen J. Turnbull