#47 Spamming SMTP sessions are kept open until SMTP idle timeout

[MyroLM]

Hi,

I am experiencing very strange behavior of SMTP sesstions in ASSP 1.10.1(16060). It looks like SPAM smtp sessions are kept until SMTP idle timeout and not dosconnected with SMTP error reply.

Notspam, okmail and greylisting sessions are OK, disconnected after few secconds. Problem is, that these spam messages are delivered over and over again instead of 1 time with SMTP error code for spamming server.

Here are some log entries:

Mar-03-16 06:14:19 Connected: 93.158.205.126:59470 -> 192.168.2.31:25 (listenPort) -> 127.0.0.1:225;
Mar-03-16 06:14:20 m-82060-00506 [History] 93.158.205.126 root@disaped.xyz to: user1@mydomain.tld Message-Score: added 50 (vbrValencePB) for Very Bad Reputation for 93.158.205.126, total score for this message is now 50;
Mar-03-16 06:14:20 m-82060-00506 [SenderBase] 93.158.205.126 root@disaped.xyz to: user1@mydomain.tld Message-Score: added 10 for Foreign Country NL(SERVERIUS HOLDING B.V.), total score for this message is now 60;
Mar-03-16 06:14:20 m-82060-00506 [GRIPvalue] 93.158.205.126 root@disaped.xyz to: user1@mydomain.tld Message-Score: added -3 for 93.158.205 in griplist (0.08), total score for this message is now 57;
Mar-03-16 06:14:20 m-82060-00506 [SPF] 93.158.205.126 root@disaped.xyz to: user1@mydomain.tld Message-Score: added -5 (spfpValencePB) for SPF pass, total score for this message is now 52;
Mar-03-16 06:14:20 m-82060-00506 [Bayesian] 93.158.205.126 root@disaped.xyz to: user1@mydomain.tld Bayesian Check [scoring:50] - Prob: 1.00000 => spam;
Mar-03-16 06:14:20 m-82060-00506 93.158.205.126 root@disaped.xyz to: user1@mydomain.tld Message-Score: added 50 for Bayesian Probability: 1.00000, total score for this message is now 102;
Mar-03-16 06:14:20 m-82060-00506 [MessageScore] 93.158.205.126 root@disaped.xyz to: user1@mydomain.tld [spam found][blocked] -- Scoring(102) surpassed limit(50) -- [100 eur zadarmo prevod spe ne dokon en] -> spam/m-82060-00506.eml;
Mar-03-16 06:14:20 m-82060-00506 [MessageScore] 93.158.205.126 root@disaped.xyz to: user1@mydomain.tld info: message forwarded to badmail@mydomain.tld;
Mar-03-16 06:17:05 [DropList] [spam found] -- found in DropList '193.189.116.0/23' -- ;
Mar-03-16 06:17:05 [SMTP Error] 554 5.7.2 Service denied, closing transmission channel;
Mar-03-16 06:19:10 [SMTP Status] 451 4.7.1 Please try again later;
Mar-03-16 06:19:10 Delayed ip 142.0.162.195, because PBBlack(350) is higher than DelayIP(50)- last penalty reason was: BayesianProbability;
Mar-03-16 06:20:45 Finished message - received DATA size: 1.49 kByte - sent DATA size: 0 Byte;
Mar-03-16 06:20:45 m-81845-00505 [DONE] 92.240.247.40 poziadavkask@poziadavka.atlantis.sk to: user2@mydomain.tld disconnected (600 seconds);
Mar-03-16 06:23:27 Connected: 185.130.5.160:47814 -> 192.168.2.31:25 (listenPort) -> 127.0.0.1:225;
Mar-03-16 06:23:27 [InvalidHELO] 185.130.5.160 info: injected STARTTLS request to 127.0.0.1;
Mar-03-16 06:23:27 [Authentication] 185.130.5.160 info: authentication - login is used;
Mar-03-16 06:23:27 185.130.5.160 info: authentication (LOGIN) realms - user:jacqueline;
Mar-03-16 06:23:27 185.130.5.160 warning: SMTP authentication failed;
Mar-03-16 06:23:27 185.130.5.160 [SMTP Error] 535 Authentication failed. Restarting authentication process.;
Mar-03-16 06:23:27 [DONE] 185.130.5.160 disconnected (0 seconds);
Mar-03-16 06:24:20 Finished message - received DATA size: 18.06 kByte - sent DATA size: 0 Byte;
Mar-03-16 06:24:20 m-82060-00506 [DONE] 93.158.205.126 root@disaped.xyz to: user1@mydomain.tld disconnected (601 seconds);
....
....
some other log lines
....
....
Mar-03-16 06:32:45 Connected: 85.90.187.34:54106 -> 192.168.2.31:25 (listenPort) -> 127.0.0.1:225;
Mar-03-16 06:32:45 m-83165-00511 [History] 85.90.187.34 bounce@edmlime.com to: user2@mydomain.tld Message-Score: added 50 (vbrValencePB) for Very Bad Reputation for 85.90.187.34, total score for this message is now 50;
Mar-03-16 06:32:45 m-83165-00511 [SenderBase] 85.90.187.34 bounce@edmlime.com to: user2@mydomain.tld Message-Score: added 10 for Foreign Country HU(OPTICON TELEKOMMUNIKACIOS HALOZATI SZOLGALTATO), total score for this message is now 60;
Mar-03-16 06:32:45 m-83165-00511 [GRIPvalue] 85.90.187.34 bounce@edmlime.com to: user2@mydomain.tld Message-Score: added -5 for 85.90.187 in griplist (0.00), total score for this message is now 55;
Mar-03-16 06:32:45 m-83165-00511 [SPF] 85.90.187.34 bounce@edmlime.com to: user2@mydomain.tld Message-Score: added -5 (spfpValencePB) for SPF pass, total score for this message is now 50;
Mar-03-16 06:32:45 m-83165-00511 [Bomb-Whitish] 85.90.187.34 bounce@edmlime.com to: user2@mydomain.tld [scoring:-8] -- bombSuspiciousRe: 'list-unsubscribe: (-8)' ;
Mar-03-16 06:32:45 m-83165-00511 85.90.187.34 bounce@edmlime.com to: user2@mydomain.tld Message-Score: added -8 for bombSuspiciousRe: 'list-unsubscribe: (-8)', total score for this message is now 42;
Mar-03-16 06:32:45 m-83165-00511 [Bayesian] 85.90.187.34 bounce@edmlime.com to: user2@mydomain.tld Bayesian Check [scoring:50] - Prob: 1.00000 => spam;
Mar-03-16 06:32:45 m-83165-00511 85.90.187.34 bounce@edmlime.com to: user2@mydomain.tld Message-Score: added 50 for Bayesian Probability: 1.00000, total score for this message is now 92;
Mar-03-16 06:32:45 m-83165-00511 [MessageScore] 85.90.187.34 bounce@edmlime.com to: user2@mydomain.tld [spam found][blocked] -- Scoring(92) surpassed limit(50) -- [Detektor oxidu uho nat ho v m m e zachr ni ivot] -> spam/m-83165-00511.eml;
Mar-03-16 06:32:46 m-83165-00511 [MessageScore] 85.90.187.34 bounce@edmlime.com to: user2@mydomain.tld info: message forwarded to badmail@mydomain.tld;
Mar-03-16 06:38:32 [DropList] [spam found] -- found in DropList '193.189.116.0/23' -- ;
Mar-03-16 06:38:32 [SMTP Error] 554 5.7.2 Service denied, closing transmission channel;
Mar-03-16 06:42:47 m-83165-00511 [Timeout] 85.90.187.34 bounce@edmlime.com to: user2@mydomain.tld Connection idle for 600 secs - timeout;

[Thomas Eckardt]

Don't know what happens, but these two lines are not related to the timeouted mail

Mar-03-16 06:38:32 [DropList] [spam found] -- found in DropList '193.189.116.0/23' -- ;
Mar-03-16 06:38:32 [SMTP Error] 554 5.7.2 Service denied, closing transmission channel;

upgrade to V2 - or use a earlyer version, if it runns better.
There are no changes made in the SMTP engine since Jan/2015

Thomas

[MyroLM]

It looks like this bug is related to Message Score.

When DoPenaltyMessage is set to Block(1) the SMTP session hangs until SMTP idle timeout, but when it is set to Testmode(4) session is ended correctly.

Logs:

Mar-04-16 08:29:50 Connected: 95.140.39.10:41161 -> 192.168.2.31:25 (listenPort) -> 127.0.0.1:225;
Mar-04-16 08:29:50 m-76590-00121 [History] 95.140.39.10 otilia.kospasztor.07.12.71@beta-groups.com to: user@mydomain.tld Message-Score: added 50 (vbrValencePB) for Very Bad Reputation for 95.140.39.10, total score for this message is now 50;
Mar-04-16 08:29:50 m-76590-00121 [SenderBase] 95.140.39.10 otilia.kospasztor.07.12.71@beta-groups.com to: user@mydomain.tld Message-Score: added 10 for Foreign Country HU(TERATRADE HUNGARY KFT), total score for this message is now 60;
Mar-04-16 08:30:00 m-76590-00121 [GRIPvalue] 95.140.39.10 otilia.kospasztor.07.12.71@beta-groups.com to: user@mydomain.tld Message-Score: added -4 for 95.140.39 in griplist (0.03), total score for this message is now 56;
Mar-04-16 08:30:00 m-76590-00121 [SPF] 95.140.39.10 otilia.kospasztor.07.12.71@beta-groups.com to: user@mydomain.tld Message-Score: added 5 (spfnValencePB) for SPF none, total score for this message is now 61;
Mar-04-16 08:30:00 m-76590-00121 [Bayesian] 95.140.39.10 otilia.kospasztor.07.12.71@beta-groups.com to: user@mydomain.tld Bayesian Check [scoring:50] - Prob: 1.00000 => spam;
Mar-04-16 08:30:00 m-76590-00121 95.140.39.10 otilia.kospasztor.07.12.71@beta-groups.com to: user@mydomain.tld Message-Score: added 50 for Bayesian Probability: 1.00000, total score for this message is now 111;
Mar-04-16 08:30:00 m-76590-00121 [MessageScore][testmode] 95.140.39.10 otilia.kospasztor.07.12.71@beta-groups.com to: user@mydomain.tld [spam found] and passing because testmode, otherwise blocked by: Scoring(111) surpassed limit(50) -- [Takto sa nikdy nepore e] -> spam/m-76590-00121.eml;
Mar-04-16 08:30:00 Admin connection from 195.78.45.138:52701; page:/addraction;
Mar-04-16 08:30:00 m-76590-00121 [MessageScore][testmode] 95.140.39.10 otilia.kospasztor.07.12.71@beta-groups.com to: user@mydomain.tld info: message forwarded to badmail@mydomain.tld;
Mar-04-16 08:30:00 Finished message - received DATA size: 3.07 kByte - sent DATA size: 3.98 kByte;
Mar-04-16 08:30:00 m-76590-00121 [DONE] 95.140.39.10 otilia.kospasztor.07.12.71@beta-groups.com to: user@mydomain.tld disconnected (10 seconds);

[Thomas Eckardt]

I've just published 1.10.1 16064 - this should fix the problem.

Thomas

[MyroLM]

Thank you Thomas, it is working great now.