Mailwasher Entreprise with postfix

Problems/tips/tricks with MailWasher Enterprise and Linux
User avatar
ajt
would rather be watching cricket
Contact:
Location: Auckland, New Zealand
Posts: 62
Joined: Mon Jan 19, 2009 4:24 pm

Re: Mailwasher Entreprise with postfix

Sun Mar 22, 2009 2:44 am

What is the status of Postfix at particular time? Before starting mwes manually see its backend running processes first.
Mail log is producing any errors?
chquek
Student Sheep
Posts: 15
Joined: Sat Mar 07, 2009 9:51 am

Re: Mailwasher Entreprise with postfix

Tue Mar 24, 2009 4:46 am

The Postfix didn't seems to be affected by that. I tried doing a smtp when Mailwasher was down and the mail was send to the recipent without any problem.

I did "ps -aux |grep mwes" and the result is as below:

root 9219 4.0 0.0 3008 776 pts/1 S+ 23:47 0:00 grep mwes

Below is the mail log at that point of time and it seems alright to me.

mail log
Mar 21 14:10:39 sg1-mwes01 postfix/smtp[11485]: 42D85122F1: to=<nigel@kodaltd.com>, relay=202.42.148.86[202.42.148.86]:25, delay=29, delays=27/0.84/0.13/1.7, dsn=5.1.1, status=bounced (host 202.42.148.86[202.42.148.86] said: 550 5.1.1 <nigel@kodaltd.com>: Recipient address rejected: User unknown in virtual mailbox table (in reply to RCPT TO command))
Mar 21 14:10:39 sg1-mwes01 postfix/smtp[11485]: 42D85122F1: to=<nigeldd@kodaltd.com>, relay=202.42.148.86[202.42.148.86]:25, delay=29, delays=27/0.84/0.13/1.9, dsn=5.1.1, status=bounced (host 202.42.148.86[202.42.148.86] said: 550 5.1.1 <nigeldd@kodaltd.com>: Recipient address rejected: User unknown in virtual mailbox table (in reply to RCPT TO command))
Mar 21 14:10:39 sg1-mwes01 postfix/smtp[11485]: 42D85122F1: to=<ong@kodaltd.com>, relay=202.42.148.86[202.42.148.86]:25, delay=30, delays=27/0.84/0.13/2.2, dsn=5.1.1, status=bounced (host 202.42.148.86[202.42.148.86] said: 550 5.1.1 <ong@kodaltd.com>: Recipient address rejected: User unknown in virtual mailbox table (in reply to RCPT TO command))
Mar 21 14:10:40 sg1-mwes01 postfix/smtp[11485]: 42D85122F1: to=<pang.hueyfan@kodaltd.com>, relay=202.42.148.86[202.42.148.86]:25, delay=30, delays=27/0.84/0.13/2.5, dsn=5.1.1, status=bounced (host 202.42.148.86[202.42.148.86] said: 550 5.1.1 <pang.hueyfan@kodaltd.com>: Recipient address rejected: User unknown in virtual mailbox table (in reply to RCPT TO command))
Mar 21 14:10:40 sg1-mwes01 postfix/smtp[11485]: 42D85122F1: to=<nancyong@kodaltd.com>, relay=202.42.148.86[202.42.148.86]:25, delay=30, delays=27/0.84/0.13/2.7, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 425BD8322C7)
Mar 21 14:10:40 sg1-mwes01 postfix/cleanup[11486]: 90F6212325: message-id=<20090321061040.90F6212325@sg1-mwes01.kodaltd.com>
Mar 21 14:10:41 sg1-mwes01 postfix/qmgr[6026]: 90F6212325: from=<>, size=6078, nrcpt=1 (queue active)
Mar 21 14:10:41 sg1-mwes01 postfix/bounce[11493]: 42D85122F1: sender non-delivery notification: 90F6212325
Mar 21 14:10:41 sg1-mwes01 postfix/qmgr[6026]: 42D85122F1: removed
Mar 21 14:10:44 sg1-mwes01 postfix/qmgr[6026]: 1780B122F5: from=<respitekc83@healthandwellnesscoaching.com>, size=1752, nrcpt=6 (queue active)
Mar 21 14:10:45 sg1-mwes01 postfix/smtpd[11479]: disconnect from unknown[119.64.119.13]
Mar 21 14:10:46 sg1-mwes01 postfix/smtp[11491]: 90F6212325: to=<fermentstn7@originalfinish.com>, relay=mx10.originalfinish.com[202.65.12.138]:25, delay=6.3, delays=0.63/0.62/2.5/2.6, dsn=5.7.1, status=bounced (host mx10.originalfinish.com[202.65.12.138] said: 554 5.7.1 <fermentstn7@originalfinish.com>: Relay access denied (in reply to RCPT TO command))
Mar 21 14:10:47 sg1-mwes01 postfix/smtp[11485]: 1780B122F5: to=<ucynthia@kodaltd.com>, relay=202.42.148.86[202.42.148.86]:25, delay=31, delays=28/1.6/0.13/0.41, dsn=5.1.1, status=bounced (host 202.42.148.86[202.42.148.86] said: 550 5.1.1 <ucynthia@kodaltd.com>: Recipient address rejected: User unknown in virtual mailbox table (in reply to RCPT TO command))
Mar 21 14:10:47 sg1-mwes01 postfix/qmgr[6026]: 90F6212325: removed
Mar 21 14:10:47 sg1-mwes01 postfix/smtp[11485]: 1780B122F5: to=<wng@kodaltd.com>, relay=202.42.148.86[202.42.148.86]:25, delay=31, delays=28/1.6/0.13/1.2, dsn=5.1.1, status=bounced (host 202.42.148.86[202.42.148.86] said: 550 5.1.1 <wng@kodaltd.com>: Recipient address rejected: User unknown in virtual mailbox table (in reply to RCPT TO command))
Mar 21 14:10:48 sg1-mwes01 postfix/smtp[11485]: 1780B122F5: to=<sooni@kodaltd.com>, relay=202.42.148.86[202.42.148.86]:25, delay=32, delays=28/1.6/0.13/1.4, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as D7C9B8322C7)
Mar 21 14:10:48 sg1-mwes01 postfix/smtp[11485]: 1780B122F5: to=<suras.kumar@kodaltd.com>, relay=202.42.148.86[202.42.148.86]:25, delay=32, delays=28/1.6/0.13/1.4, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as D7C9B8322C7)
Mar 21 14:10:48 sg1-mwes01 postfix/smtp[11485]: 1780B122F5: to=<wkteh@kodaltd.com>, relay=202.42.148.86[202.42.148.86]:25, delay=32, delays=28/1.6/0.13/1.4, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as D7C9B8322C7)
Mar 21 14:10:48 sg1-mwes01 postfix/smtp[11485]: 1780B122F5: to=<yonglee@kodaltd.com>, relay=202.42.148.86[202.42.148.86]:25, delay=32, delays=28/1.6/0.13/1.4, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as D7C9B8322C7)
Mar 21 14:10:48 sg1-mwes01 postfix/cleanup[11470]: 62919122F1: message-id=<20090321061048.62919122F1@sg1-mwes01.kodaltd.com>
Mar 21 14:10:49 sg1-mwes01 postfix/qmgr[6026]: 62919122F1: from=<>, size=4475, nrcpt=1 (queue active)
Mar 21 14:10:49 sg1-mwes01 postfix/bounce[11493]: 1780B122F5: sender non-delivery notification: 62919122F1
Mar 21 14:10:49 sg1-mwes01 postfix/qmgr[6026]: 1780B122F5: removed
Mar 21 14:10:50 sg1-mwes01 postfix/smtp[11491]: 62919122F1: to=<respitekc83@healthandwellnesscoaching.com>, relay=p.nsm.ctmail.com[216.163.188.57]:25, delay=1.9, delays=0.62/0.22/0.53/0.48, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 77A496A124DA3)
Mar 21 14:10:50 sg1-mwes01 postfix/qmgr[6026]: 62919122F1: removed
Mar 21 14:11:04 sg1-mwes01 postfix/smtp[11481]: connect to mail2.siteamerica.com[209.67.50.14]:25: Connection timed out
Mar 21 14:11:04 sg1-mwes01 postfix/smtp[11481]: 13D4D12291: to=<modestestc71@separationmanagement.com>, relay=none, delay=48966, delays=48913/21/32/0, dsn=4.4.1, status=deferred (connect to mail2.siteamerica.com[209.67.50.14]:25: Connection timed out)
Mar 21 14:13:04 sg1-mwes01 postfix/smtpd[11497]: warning: dict_nis_init: NIS domain name not set - NIS lookups disabled
Mar 21 14:13:04 sg1-mwes01 postfix/smtpd[11497]: connect from unknown[unknown]
Mar 21 14:13:05 sg1-mwes01 postfix/smtpd[11497]: warning: milter inet:127.0.0.1:4049: can't read SMFIC_CONNECT reply packet header: Success
Mar 21 14:13:06 sg1-mwes01 postfix/smtpd[11497]: lost connection after CONNECT from unknown[unknown]
Mar 21 14:13:06 sg1-mwes01 postfix/smtpd[11497]: disconnect from unknown[unknown]
Mar 21 14:15:07 sg1-mwes01 postfix/qmgr[6026]: 50D1C121F7: from=<>, size=3869, nrcpt=1 (queue active)
Mar 21 14:15:12 sg1-mwes01 postfix/qmgr[6026]: 4495D12217: from=<>, size=5701, nrcpt=1 (queue active)
Mar 21 14:15:19 sg1-mwes01 postfix/qmgr[6026]: 4DA90121EE: from=<>, size=4859, nrcpt=1 (queue active)
Mar 21 14:15:21 sg1-mwes01 postfix/smtp[11539]: 50D1C121F7: lost connection with q0.netfirms.com[70.42.30.139] while receiving the initial server greeting
Mar 21 14:15:22 sg1-mwes01 postfix/smtp[11539]: 50D1C121F7: lost connection with q0.netfirms.com[70.42.30.11] while receiving the initial server greeting
User avatar
ajt
would rather be watching cricket
Contact:
Location: Auckland, New Zealand
Posts: 62
Joined: Mon Jan 19, 2009 4:24 pm

Re: Mailwasher Entreprise with postfix

Tue Mar 24, 2009 11:58 am

Could you enable mwes logging in debug mode and send its logs? Change log_level=1 in /etc/mwes.conf and restart mwes!
In mwes log you posted:

2009-03-21 14:10:44 [3066911632] Info: Processed = 347 - 3, Emails(ok) = 51 - 2, FA = 175 - 0, RBL = 121 - 2, Black listed = 0 - 0, Custom filter = 0 - 0, FA(IP) = 0 - 0, Empty Email Body = 0 - 0, Uploaded = 121 - 2,

Following entry shows mwes starting again. Is this when you manually start mwes after seeing it hanged up?

2009-03-21 20:11:05 [3084130624] Info: starting mwes version 2.6.3 {U}

Cheers
chquek
Student Sheep
Posts: 15
Joined: Sat Mar 07, 2009 9:51 am

Re: Mailwasher Entreprise with postfix

Thu Mar 26, 2009 5:53 am

Hi,

Yes I did a restart previously.

Below is the mwes.log after switching it to debug mode. Pls note that I only copied the initial start of Mailwasher and before stopped as it is a very long list.
Let know if it will be sufficient.

2009-03-25 00:16:28 [3083471168] Info: starting mwes version 2.6.3 {U}
2009-03-25 00:16:28 [3083471168] Info: environment....
2009-03-25 00:16:28 [3083471168] Info: database_location::/opt/mwes
2009-03-25 00:16:28 [3083471168] Info: listen_port::4044
2009-03-25 00:16:28 [3083471168] Info: log_level::1
2009-03-25 00:16:28 [3083471168] Info: logging::/var/log/mwes/
2009-03-25 00:16:28 [3083471168] Info: milter_port::inet:4049@127.0.0.1
2009-03-25 00:16:28 [3083471168] Info: root_document::/opt/mwes/mwes/
2009-03-25 00:16:28 [3083471168] Info: Initialising WebManager....
2009-03-25 00:16:29 [3083471168] Info: Initialising database....
2009-03-25 00:16:29 [3083471168] Info: Initialising database configure table....
2009-03-25 00:16:29 [3083471168] Info: Initialising database white listing table....
2009-03-25 00:16:29 [3083471168] Info: Initialising database black listing table....
2009-03-25 00:16:29 [3083471168] Info: Not written... Initialising database filter white listing table....
2009-03-25 00:16:29 [3083471168] Info: Initialising database filter black listing table....
2009-03-25 00:16:29 [3083471168] Info: Initialising database rbl listing table....
2009-03-25 00:16:29 [3083471168] Info: Initialising database quarantined table....
2009-03-25 00:16:29 [3083471168] Info: Initialising database gray listing table....
2009-03-25 00:16:29 [3083471168] Info: Initialising database white listing ip table....
2009-03-25 00:16:29 [3083471168] Info: DatabaseManager::UpgradeDatabase - version 8 ok
2009-03-25 00:16:29 [3083471168] Info: Starting StatThread....
2009-03-25 00:16:29 [3083471168] Info: Starting FilterManagerThreads....
2009-03-25 00:16:29 [3083471168] Info: Starting UploadManagerThread....
2009-03-25 00:16:29 [3083471168] Info: Starting ExchangeConduitThread....
2009-03-25 00:16:29 [3083471168] Info: Starting MilterConduitThread....
2009-03-25 00:16:29 [3083471168] Info: Starting HouseKeepingTask....
2009-03-25 00:18:03 [3066682256] Info: Processed = 1 - 1, Emails(ok) = 0 - 0, FA = 0 - 0, RBL = 0 - 0, Black listed = 0 - 0, Custom filter = 0 - 0, FA(IP) = 0 - 0, Empty Email Body = 0 - 0, Uploaded = 0 - 0,
2009-03-25 00:18:03 [3007933328] Debug: Start Processing Email ID(1)...
2009-03-25 00:18:03 [3007933328] Debug: Successfully added email ID (1) to FilterManagerThread Queue...
2009-03-25 00:18:06 [3058289552] Debug: Successfully Connected to CFS on URL (native.first-alert.net)...
2009-03-25 00:18:06 [3058289552] Debug: Email ID (1) Not found in CFS...
2009-03-25 00:18:06 [3058289552] Debug: Successfully disconnected from CFS...
2009-03-25 00:18:07 [3007933328] Debug: Email ID (1) Known as SPAM in RBL(zen.spamhaus.org) IP[190.135.61.133]...
2009-03-25 00:18:07 [3007933328] Debug: added (1) RBL IP(190.135.61.133) to cache...
2009-03-25 00:18:07 [3007933328] Debug: Email ID (1) (found in RBL)...
2009-03-25 00:18:07 [3007933328] Debug: RBL [190.135.61.133,r190-135-61-133.dialup.adsl.anteldata.net.uy,<tourniquetse968@sexcrimereporting.com>, <sooni@kodaltd.com>]
2009-03-25 00:18:07 [3007933328] Debug: QuarantinedTable Email ID (1) added to database...
2009-03-25 00:18:07 [3007933328] Debug: QuarantinedTable Email ID (1) added to cache...
2009-03-25 00:18:07 [3007933328] Debug: End Processing Email ID(1) DISCARD...
2009-03-25 00:18:09 [3049896848] Debug: Successfully Connected to CFS on URL (native.first-alert.net)...
2009-03-25 00:18:10 [3049896848] Debug: Email ID (1) Uploaded
2009-03-25 00:18:10 [3049896848] Debug: Successfully disconnected from CFS...

Skipped to the time before it stopped:

2009-03-25 01:43:31 [2997877648] Debug: Start Processing Email ID(115)...
2009-03-25 01:43:31 [2997877648] Debug: Successfully added email ID (115) to FilterManagerThread Queue...
2009-03-25 01:43:33 [3058289552] Debug: Successfully Connected to CFS on URL (native.first-alert.net)...
2009-03-25 01:43:34 [3058289552] Debug: Email ID (115) Known as SPAM in CFS...
2009-03-25 01:43:34 [3058289552] Debug: Email ID (115) added to cache...
2009-03-25 01:43:34 [3058289552] Debug: added Email ID(115) (52) FA IP(201.95.14.217) to cache...
2009-03-25 01:43:34 [2997877648] Debug: FA [201.95.14.217,201-95-14-217.dsl.telesp.net.br,<shinobut@freshdrop.net>, <wkteh@kodaltd.com>]
2009-03-25 01:43:34 [3058289552] Debug: Successfully disconnected from CFS...
2009-03-25 01:43:34 [2997877648] Debug: QuarantinedTable Email ID (115) added to database...
2009-03-25 01:43:34 [2997877648] Debug: QuarantinedTable Email ID (115) added to cache...
2009-03-25 01:43:34 [2997877648] Debug: End Processing Email ID(115) DISCARD...
2009-03-25 01:43:48 [2997877648] Debug: Start Processing Email ID(116)...
2009-03-25 01:43:48 [2997877648] Debug: Successfully added email ID (116) to FilterManagerThread Queue...
2009-03-25 01:43:50 [3058289552] Debug: Successfully Connected to CFS on URL (native.first-alert.net)...
2009-03-25 01:43:51 [3058289552] Debug: Email ID (116) Not found in CFS...
2009-03-25 01:43:51 [3058289552] Debug: Successfully disconnected from CFS...
2009-03-25 01:43:51 [2997877648] Debug: Email ID (116) Known as SPAM in RBL(zen.spamhaus.org) IP[78.96.118.28]...
2009-03-25 01:43:51 [2997877648] Debug: added (25) RBL IP(78.96.118.28) to cache...
2009-03-25 01:43:51 [2997877648] Debug: Email ID (116) (found in RBL)...
2009-03-25 01:43:51 [2997877648] Debug: RBL [78.96.118.28,xxx-392630e019d,<kefwyowildlifediz@wyowildlife.com>, <koda.malaysia@kodaltd.com> <koda@kodaltd.com>]
2009-03-25 01:43:51 [2997877648] Debug: QuarantinedTable Email ID (116) added to database...
2009-03-25 01:43:51 [2997877648] Debug: QuarantinedTable Email ID (116) added to cache...
2009-03-25 01:43:51 [2997877648] Debug: End Processing Email ID(116) DISCARD...
2009-03-25 01:43:53 [3049896848] Debug: Successfully Connected to CFS on URL (native.first-alert.net)...
2009-03-25 01:43:54 [3049896848] Debug: Email ID (116) Uploaded
2009-03-25 01:43:54 [3049896848] Debug: Successfully disconnected from CFS...
2009-03-25 01:45:37 [3066682256] Info: Processed = 117 - 2, Emails(ok) = 5 - 0, FA = 86 - 1, RBL = 25 - 1, Black listed = 0 - 0, Custom filter = 0 - 0, FA(IP) = 0 - 0, Empty Email Body = 0 - 0, Uploaded = 25 - 1,
2009-03-25 01:45:37 [2997877648] Debug: Start Processing Email ID(117)...
2009-03-25 01:45:37 [2997877648] Debug: Successfully added email ID (117) to FilterManagerThread Queue...
2009-03-25 01:45:40 [3058289552] Debug: Successfully Connected to CFS on URL (native.first-alert.net)...
2009-03-25 01:45:40 [3058289552] Debug: Email ID (117) Not found in CFS...
2009-03-25 01:45:40 [3058289552] Debug: Successfully disconnected from CFS...
2009-03-25 01:45:41 [2997877648] Debug: Email ID (117) Known as SPAM in RBL(zen.spamhaus.org) IP[83.131.223.142]...
2009-03-25 01:45:41 [2997877648] Debug: added (26) RBL IP(83.131.223.142) to cache...
2009-03-25 01:45:41 [2997877648] Debug: Email ID (117) (found in RBL)...
2009-03-25 01:45:41 [2997877648] Debug: RBL [83.131.223.142,83-131-223-142.adsl.net.t-com.hr,<ghwjbotsecg@brandbox.com>, <nelsoh@kodaltd.com>]
2009-03-25 01:45:41 [2997877648] Debug: QuarantinedTable Email ID (117) added to database...
2009-03-25 01:45:41 [2997877648] Debug: QuarantinedTable Email ID (117) added to cache...
2009-03-25 01:45:41 [2997877648] Debug: End Processing Email ID(117) DISCARD...
User avatar
ajt
would rather be watching cricket
Contact:
Location: Auckland, New Zealand
Posts: 62
Joined: Mon Jan 19, 2009 4:24 pm

Re: Mailwasher Entreprise with postfix

Thu Mar 26, 2009 12:10 pm

We need more information to diagnose this issue . Could you tar or zip mail.log & mwes.log files and send it to ali@firetrust.com
Kindly cross check if you are running any cronjob or backup script which may disrupt postfix or mwes processes. What are the specs of your box.
Mwes 2.63 running on Ubuntu 8.0.4.2 LTS with Postfix 2.5.1 + Box has 64 Bit processor+512 MB RAM and it is handling 300000 mails/24 hours.
chquek
Student Sheep
Posts: 15
Joined: Sat Mar 07, 2009 9:51 am

Re: Mailwasher Entreprise with postfix

Thu Apr 02, 2009 5:25 am

Hi,

Sorry for the delay.

I have just sent you the log file for both the mail and mwes.

Currently I only have the follow items in the cron.daily:

apt aptitude bsdmainutils dspam find logrotate man-db ntpdate standard sysklogd

Is MWES related to dspam?

I am running this in a VM which has 1 Duo-Core Intel Pentium D 3.00GHz and 2 GB of memory. At the moment I only have 2 VMs running and should not be resource intensive.
chquek
Student Sheep
Posts: 15
Joined: Sat Mar 07, 2009 9:51 am

Re: Mailwasher Entreprise with postfix

Thu Apr 02, 2009 5:35 am

My apology. I was looking at the wrong server.

What I have in the cron.daily are as follow:

apt aptitude bsdmainutils logrotate man-db mlocate ntp standard sysklogd

What I have done now is that I created a cron job which will start mwesd every hourly. (Keepin my fingers cross)
User avatar
nick.bolton
The Big Cheese
Posts: 2468
Joined: Thu Aug 28, 2008 4:02 pm

Re: Mailwasher Entreprise with postfix

Thu Apr 02, 2009 10:08 am

In the config file can you please add the following
Linux: /etc/mwes.conf


log_level=1
cfs_max_cache_size=1000
rbl_max_cache_size=1000
use_quarantine_cache=0

This seems to have fixed a similar problem with another user.
chquek
Student Sheep
Posts: 15
Joined: Sat Mar 07, 2009 9:51 am

Re: Mailwasher Entreprise with postfix

Thu Apr 02, 2009 10:22 pm

So far so good, mwes is still running.

Seems good. I will continue to monitor.

Thanks for your help.
chquek
Student Sheep
Posts: 15
Joined: Sat Mar 07, 2009 9:51 am

Re: Mailwasher Entreprise with postfix

Fri Apr 03, 2009 5:16 am

mwes stopped again after approximately 6 hours.

Will it helps if I increase both max cache to maybe 4000 help? Any impact to the system if i do that?
User avatar
nick.bolton
The Big Cheese
Posts: 2468
Joined: Thu Aug 28, 2008 4:02 pm

Re: Mailwasher Entreprise with postfix

Fri Apr 03, 2009 5:25 am

Should be fine, the default before this was much higher. If you want to wait, then i'll get the definitive answer from the developers in about 4 hours (not at work yet)
User avatar
nick.bolton
The Big Cheese
Posts: 2468
Joined: Thu Aug 28, 2008 4:02 pm

Re: Mailwasher Entreprise with postfix

Fri Apr 03, 2009 10:27 am

Can you please send me your logs to nick.bolton*firetrust.com (replacing * with @)

The changed logging level we set should give us more information about what went wrong. Developers said not to worry about increasing the cache size

Logs in
/var/logs/mwes

Thanks
User avatar
nick.bolton
The Big Cheese
Posts: 2468
Joined: Thu Aug 28, 2008 4:02 pm

Re: Mailwasher Entreprise with postfix

Mon Apr 06, 2009 3:03 pm

We've got a new update here which hopefully fixes the problem (and increases the amount of logging). Can you please try it

http://s3.amazonaws.com/Firetrust/mwes/mwes-264.tar.gz

Thanks

Return to “Linux Specific”