View Issue Details

IDProjectCategoryView StatusLast Update
0003774SOGoActiveSyncpublic2017-07-05 03:08
Reporteralexeilevinzon Assigned Toludovic  
PriorityhighSeveritycrashReproducibilityalways
Status resolvedResolutionfixed 
Platform[Server] LinuxOSRHEL/CentOSOS Version6
Product Version3.1.4 
Fixed in Version3.2.0 
Summary0003774: Sogo AES not reporting outlook about SMTP code '554'
Description

Sogo AES not reporting back to outlook about 554 error.

When the message is not sent by postfix, and error 554 returned, sogo not report it to outlook.

the message stays in outlook and outlook tries to resend it every minute.

in smpt its works, outlook process the message and return back message that the mail not sent, but in aes its got no report and keep try to resend the message for ever.

Additional Information

thats what i got in sogo log:

Jul 23 02:40:32 sogod [18139]: |SOGo| starting method 'POST' on uri '/SOGo/Microsoft-Server-ActiveSync?Cmd=SendMail&User=10@barcol.pw&DeviceId=B713B26DE524468096AC3D8FB194FF79&DeviceType=WindowsOutlook15'
Jul 23 02:40:32 sogod [18139]: <0x0x7fa2e53b70d8[SOGoActiveSyncDispatcher]> EAS - request for device B713B26DE524468096AC3D8FB194FF79: <?xml version="1.0"?>
<!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/&quot;>
<SendMail xmlns="ComposeMail:">
<ClientId>{95D0598B-53EE-4B95-9B84-5BE3CE9D81B1}</ClientId>
<SaveInSentItems/>
<MIME>RnJvbTogPDEwQGJhcmNvbC5wdz4NClRvOiA8YWxleGVpbGV2aW56b25AZ21haWwuY29tPg0KU3ViamVjdDogdGVzdA0KRGF0ZTogU2F0LCAyMyBKdWwgMjAxNiAwOTozODoyOCArMDMwMA0KTWVzc2FnZS1JRDogPDAwNDkwMWQxZTRhZCQxYzFmMTgxMCQ1NDVkNDgzMCRAYmFyY29sLnB3Pg0KTUlNRS1WZXJzaW9uOiAxLjANCkNvbnRlbnQtVHlwZTogbXVsdGlwYXJ0L2FsdGVybmF0aXZlOw0KCWJvdW5kYXJ5PSItLS0tPV9OZXh0UGFydF8wMDBfMDA0QV8wMUQxRTRDNi40MTZDNTAxMCINClgtTWFpbGVyOiBNaWNyb3NvZnQgT3V0bG9vayAxNi4wDQpUaHJlYWQtSW5kZXg6IEFkSGtyTkVDQW0wbW5qL0lSQUtDMDZaYytTdnd3Zz09DQpDb250ZW50LUxhbmd1YWdlOiBoZQ0KDQpUaGlzIGlzIGEgbXVsdGlwYXJ0IG1lc3NhZ2UgaW4gTUlNRSBmb3JtYXQuDQoNCi0tLS0tLT1fTmV4dFBhcnRfMDAwXzAwNEFfMDFEMUU0QzYuNDE2QzUwMTANCkNvbnRlbnQtVHlwZTogdGV4dC9wbGFpbjsNCgljaGFyc2V0PSJ3aW5kb3dzLTEyNTUiDQpDb250ZW50LVRyYW5zZmVyLUVuY29kaW5nOiBiYXNlNjQNCg0KNE9QMzRPUDM0T1AzNEEwS0RRbz0NCg0KLS0tLS0tPV9OZXh0UGFydF8wMDBfMDA0QV8wMUQxRTRDNi40MTZDNTAxMA0KQ29udGVudC1UeXBlOiB0ZXh0L2h0bWw7DQoJY2hhcnNldD0id2luZG93cy0xMjU1Ig0KQ29udGVudC1UcmFuc2Zlci1FbmNvZGluZzogcXVvdGVkLXByaW50YWJsZQ0KDQo8aHRtbCB4bWxuczp2PTNEInVybjpzY2hlbWFzLW1pY3Jvc29mdC1jb206dm1sIiA9DQp4bWxuczpvPTNEInVybjpzY2hlbWFzLW1pY3Jvc29mdC1jb206b2ZmaWNlOm9mZmljZSIgPQ0KeG1sbnM6dz0zRCJ1cm46c2NoZW1hcy1taWNyb3NvZnQtY29tOm9mZmljZTp3b3JkIiA9DQp4bWxuczptPTNEImh0dHA6Ly9zY2hlbWFzLm1pY3Jvc29mdC5jb20vb2ZmaWNlLzIwMDQvMTIvb21tbCIgPQ0KeG1sbnM9M0QiaHR0cDovL3d3dy53My5vcmcvVFIvUkVDLWh0bWw0MCI+PGhlYWQ+PG1ldGEgPQ0KaHR0cC1lcXVpdj0zRENvbnRlbnQtVHlwZSBjb250ZW50PTNEInRleHQvaHRtbDsgPQ0KY2hhcnNldD0zRHdpbmRvd3MtMTI1NSI+PG1ldGEgbmFtZT0zREdlbmVyYXRvciBjb250ZW50PTNEIk1pY3Jvc29mdCBXb3JkID0NCjE1IChmaWx0ZXJlZCBtZWRpdW0pIj48c3R5bGU+PCEtLQ0KLyogRm9udCBEZWZpbml0aW9ucyAqLw0KQGZvbnQtZmFjZQ0KCXtmb250LWZhbWlseToiQ2FtYnJpYSBNYXRoIjsNCglwYW5vc2UtMToyIDQgNSAzIDUgNCA2IDMgMiA0O30NCkBmb250LWZhY2UNCgl7Zm9udC1mYW1pbHk6Q2FsaWJyaTsNCglwYW5vc2UtMToyIDE1IDUgMiAyIDIgNCAzIDIgNDt9DQovKiBTdHlsZSBEZWZpbml0aW9ucyAqLw0KcC5Nc29Ob3JtYWwsIGxpLk1zb05vcm1hbCwgZGl2Lk1zb05vcm1hbA0KCXttYXJnaW46MGNtOw0KCW1hcmdpbi1ib3R0b206LjAwMDFwdDsNCgl0ZXh0LWFsaWduOnJpZ2h0Ow0KCWRpcmVjdGlvbjpydGw7DQoJdW5pY29kZS1iaWRpOmVtYmVkOw0KCWZvbnQtc2l6ZToxMS4wcHQ7DQoJZm9udC1mYW1pbHk6IkNhbGlicmkiLHNhbnMtc2VyaWY7fQ0KYTpsaW5rLCBzcGFuLk1zb0h5cGVybGluaw0KCXttc28tc3R5bGUtcHJpb3JpdHk6OTk7DQoJY29sb3I6IzA1NjNDMTsNCgl0ZXh0LWRlY29yYXRpb246dW5kZXJsaW5lO30NCmE6dmlzaXRlZCwgc3Bhbi5Nc29IeXBlcmxpbmtGb2xsb3dlZA0KCXttc28tc3R5bGUtcHJpb3JpdHk6OTk7DQoJY29sb3I6Izk1NEY3MjsNCgl0ZXh0LWRlY29yYXRpb246dW5kZXJsaW5lO30NCnNwYW4uRW1haWxTdHlsZTE3DQoJe21zby1zdHlsZS10eXBlOnBlcnNvbmFsLWNvbXBvc2U7DQoJZm9udC1mYW1pbHk6IkNhbGlicmkiLHNhbnMtc2VyaWY7DQoJY29sb3I6d2luZG93dGV4dDt9DQouTXNvQ2hwRGVmYXVsdA0KCXttc28tc3R5bGUtdHlwZTpleHBvcnQtb25seTsNCglmb250LWZhbWlseToiQ2FsaWJyaSIsc2Fucy1zZXJpZjt9DQpAcGFnZSBXb3JkU2VjdGlvbjENCgl7c2l6ZTo2MTIuMHB0IDc5Mi4wcHQ7DQoJbWFyZ2luOjcyLjBwdCA5MC4wcHQgNzIuMHB0IDkwLjBwdDt9DQpkaXYuV29yZFNlY3Rpb24xDQoJe3BhZ2U6V29yZFNlY3Rpb24xO30NCi0tPjwvc3R5bGU+PCEtLVtpZiBndGUgbXNvIDldPjx4bWw+DQo8bzpzaGFwZWRlZmF1bHRzIHY6ZXh0PTNEImVkaXQiIHNwaWRtYXg9M0QiMTAyNiIgLz4NCjwveG1sPjwhW2VuZGlmXS0tPjwhLS1baWYgZ3RlIG1zbyA5XT48eG1sPg0KPG86c2hhcGVsYXlvdXQgdjpleHQ9M0QiZWRpdCI+DQo8bzppZG1hcCB2OmV4dD0zRCJlZGl0IiBkYXRhPTNEIjEiIC8+DQo8L286c2hhcGVsYXlvdXQ+PC94bWw+PCFbZW5kaWZdLS0+PC9oZWFkPjxib2R5IGxhbmc9M0RFTi1VUyA9DQpsaW5rPTNEIiMwNTYzQzEiIHZsaW5rPTNEIiM5NTRGNzIiPjxkaXYgY2xhc3M9M0RXb3JkU2VjdGlvbjE+PHAgPQ0KY2xhc3M9M0RNc29Ob3JtYWwgZGlyPTNEUlRMIHN0eWxlPTNEJ3RleHQtaW5kZW50OjM2LjBwdCc+PHNwYW4gbGFuZz0zREhFID0NCnN0eWxlPTNEJ2ZvbnQtZmFtaWx5OiJBcmlhbCIsc2Fucy1zZXJpZic+PUUwPUUzPUY3PUUwPUUzPUY3PUUwPUUzPUY3PUUwPC89DQpzcGFuPjxzcGFuIGRpcj0zRExUUj48bzpwPjwvbzpwPjwvc3Bhbj48L3A+PC9kaXY+PC9ib2R5PjwvaHRtbD4NCi0tLS0tLT1fTmV4dFBhcnRfMDAwXzAwNEFfMDFEMUU0QzYuNDE2QzUwMTAtLQ0K</MIME>
</SendMail>

Jul 23 02:40:32 sogod [18147]: <0x0x7fa2e5181788[SOGoActiveSyncDispatcher]> Sleeping 15 seconds while detecting changes in Ping...
Jul 23 02:40:33 sogod [18139]: <0x0x7fa2e56ab048[SOGoMailer]> error with recipient 'alexeilevinzon@gmail.com'
Jul 23 02:40:33 sogod [18139]: [ERROR] <0x0x7fa2e56af7c8[NSMutableDataMalloc]> wbxml2xmlFromContent: failed: The character set cannot be found.

Jul 23 02:40:33 sogod [18139]: [ERROR] <0x0x7fa2e56af7c8[NSMutableDataMalloc]> Original data written to: /tmp/localhost4_46db_1d4348a5_1.data

and thats waht i got in /tmp/localhost4_46db_1d4348a5_1.data

FATAL ERROR occured during SendMail

TagsNo tags attached.

Activities

zhb

zhb

2016-07-25 02:12

reporter   ~0010539

SOGo should return the original SMTP code (and text) to the MUA.

zhb

zhb

2016-07-25 02:30

reporter   ~0010540

I'd like to add some more details about this issue since the reporter is an iRedMail user.

We have blacklisting for outbound email, and this user is not allowed to send email to, for example, @gmail.com. So when he tries to send email to <someone>@gmail.com on SOGo web UI, the mail will be rejected with SMTP code/text "554 REJECT Blacklisted", SOGo web ui reports error like "All recipients are invalid". If send with Outlook (via ActiveSync), then mail cannot be sent out, and Outlook slightly defers it and keep trying to send it out again and again in the background, until raise a error which causes user really confused. According to the debug message (pasted in reporter's post), SOGo didn't send the original SMTP code/text to Outlook, so this is the root cause.

tfu

tfu

2016-07-25 07:32

reporter   ~0010542

Currently, when sendMail fails the requests returns with a HTTP-500.
According to https://msdn.microsoft.com/en-us/library/ee218647%28v=exchg.80%29.aspx with protocol versions 14+ the response should contain a status element with a status 1XX.
But event with attached patch outlook doesn't stop to retry the sendmail.

tfu

tfu

2016-07-25 07:35

reporter  

3774.diff (4,568 bytes)   
diff --git a/ActiveSync/SOGoActiveSyncDispatcher.m b/ActiveSync/SOGoActiveSyncDispatcher.m
index 20c5ba6..bd43069 100644
--- a/ActiveSync/SOGoActiveSyncDispatcher.m
+++ b/ActiveSync/SOGoActiveSyncDispatcher.m
@@ -2925,7 +2925,7 @@ void handle_eas_terminate(int signum)
 
   from = [message headersForKey: @"from"];
 
-        from = [NSMutableArray arrayWithObject: @"lala@lala.com"];
+        //from = [NSMutableArray arrayWithObject: @"lala@lala.com"];
 
   if (![from count] || ![self _isEMailValid: [[from objectAtIndex: 0] pureEMailAddress]] ||
       [[[from objectAtIndex: 0] pureEMailAddress] isEqualToString: [from objectAtIndex: 0]] ||
@@ -2950,7 +2950,7 @@ void handle_eas_terminate(int signum)
       else
         new_from_header = [[NSString stringWithFormat: @"From: %@\r\n", email] dataUsingEncoding: NSUTF8StringEncoding];
 
-        new_from_header = [[NSString stringWithString:@"lala@lala.com"]  dataUsingEncoding: NSUTF8StringEncoding];
+//        new_from_header = [[NSString stringWithString:@"lala@lala.com"]  dataUsingEncoding: NSUTF8StringEncoding];
 
       bytes = [data bytes];
       len = [data length];
@@ -3026,8 +3026,28 @@ void handle_eas_terminate(int signum)
 
   if (error)
     {
-      [theResponse setStatus: 500];
-      [theResponse appendContentString: @"FATAL ERROR occured during SendMail"];
+      if ([[context objectForKey: @"ASProtocolVersion"] floatValue] >= 14.0)
+        {
+          NSMutableString *s;
+          NSData *d;
+
+          s = [NSMutableString string];
+
+          [s appendString: @"<?xml version=\"1.0\" encoding=\"utf-8\"?>"];
+          [s appendString: @"<!DOCTYPE ActiveSync PUBLIC \"-//MICROSOFT//DTD ActiveSync//EN\" \"http://www.microsoft.com/\">"];
+          [s appendString: @"<SendMail xmlns=\"ComposeMail:\">"];
+          [s appendString: @"<Status>120</Status>"];
+          [s appendString: @"</SendMail>"];
+
+           d = [[s dataUsingEncoding: NSUTF8StringEncoding] xml2wbxml];
+
+           [theResponse setContent: d];
+        }
+      else
+        {
+          [theResponse setStatus: 500];
+          [theResponse appendContentString: @"FATAL ERROR occured during SendMail"];
+        }
     }
 }
 
@@ -3534,8 +3554,28 @@ void handle_eas_terminate(int signum)
       
       if (error)
         {
-          [theResponse setStatus: 500];
-          [theResponse appendContentString: @"FATAL ERROR occured during SmartForward"];
+          if ([[context objectForKey: @"ASProtocolVersion"] floatValue] >= 14.0)
+            {
+              NSMutableString *s;
+              NSData *d;
+
+              s = [NSMutableString string];
+
+              [s appendString: @"<?xml version=\"1.0\" encoding=\"utf-8\"?>"];
+              [s appendString: @"<!DOCTYPE ActiveSync PUBLIC \"-//MICROSOFT//DTD ActiveSync//EN\" \"http://www.microsoft.com/\">"];
+              [s appendFormat: @"<%@ xmlns=\"ComposeMail:\">", (isSmartForward) ? @"SmartForward" : @"SmartReply"];
+              [s appendString: @"<Status>120</Status>"];
+              [s appendFormat: @"</%@>", (isSmartForward) ? @"SmartForward" : @"SmartReply"];
+
+              d = [[s dataUsingEncoding: NSUTF8StringEncoding] xml2wbxml];
+
+              [theResponse setContent: d];
+            }
+          else
+            {
+              [theResponse setStatus: 500];
+              [theResponse appendContentString: @"FATAL ERROR occured during SmartForward"];
+            }
         }
       else if (!isSmartForward)
         {
@@ -3743,7 +3783,7 @@ void handle_eas_terminate(int signum)
   [theResponse setHeader: @"Sync,SendMail,SmartForward,SmartReply,GetAttachment,GetHierarchy,CreateCollection,DeleteCollection,MoveCollection,FolderSync,FolderCreate,FolderDelete,FolderUpdate,MoveItems,GetItemEstimate,MeetingResponse,Search,Settings,Ping,ItemOperations,ResolveRecipients,ValidateCert"  forKey: @"MS-ASProtocolCommands"];
   [theResponse setHeader: @"2.5,12.0,12.1,14.0,14.1"  forKey: @"MS-ASProtocolVersions"];
 
-  if (debugOn && [[theResponse headerForKey: @"Content-Type"] isEqualToString:@"application/vnd.ms-sync.wbxml"] && [[theResponse content] length])
+  if (debugOn && [[theResponse headerForKey: @"Content-Type"] isEqualToString:@"application/vnd.ms-sync.wbxml"] && [[theResponse content] length] && !([(WOResponse *)theResponse status] == 500))
     [self logWithFormat: @"EAS - response for device %@: %@", [context objectForKey: @"DeviceId"], [[[NSString alloc] initWithData: [[theResponse content] wbxml2xml] encoding: NSUTF8StringEncoding] autorelease]];
 
   RELEASE(context);
3774.diff (4,568 bytes)   
alexeilevinzon

alexeilevinzon

2016-09-11 08:18

reporter   ~0010640

any news on this issue?

emilio.fonseca

emilio.fonseca

2016-09-20 19:05

reporter   ~0010650

I think it is the same issue, here is what I got in my sogo.log:

Sep 20 15:15:31 sogod [66]: nginx-mail_2.mail "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=user@domain&DeviceId=SEC1C150B835F637&DeviceType=SAMSUNGGTI8552B HTTP/1.1" 200 12/18 0.045 - - 140K
Sep 20 15:15:33 sogod [66]: [ERROR] <0x0x5593fabb3c10[NSMutableDataMalloc]> wbxml2xmlFromContent: failed: Bad string length, can't convert

Sep 20 15:15:33 sogod [66]: [ERROR] <0x0x5593fabb3c10[NSMutableDataMalloc]> Original data written to: /tmp/d495ff03feb8_42_1d91b443_1.data

In my case, the file .data is a binary file.
Any news in this issue?

ludovic

ludovic

2016-09-20 19:06

administrator   ~0010651

No, send it to me privately - gzip -9 it before.

alexeilevinzon

alexeilevinzon

2016-10-05 20:05

reporter   ~0010722

Hello,

I updated to 3.2 (where the issue should be fixed).
but when I try to send email to blocked recipient, mail stucks in outgoing folder in outlook and keep try to resend it every couple minutes.

thats what I see in the logs:
Oct 05 15:57:54 sogod [25033]: <0x0x3a87d4872b8[SOGoMailer]> error with recipient 'blabla@gmail.com'.

Outlook version 2016

the outlook should stop to resend the email and notify me that there is an error or something...

Thanks

ludovic

ludovic

2016-10-05 20:07

administrator   ~0010723

Ask Microsoft to do that, not us. If Outlook keeps trying to send the mail, there's nothing SOGo can do about this.

We report the proper error code.

Related Changesets

sogo: master 9bbffe48

2016-09-23 11:28

ludovic


Details Diff
(fix) handle 120 EAS status code when message submission fails (fixes 0003774) Affected Issues
0003774
mod - ActiveSync/SOGoActiveSyncDispatcher.m Diff File

sogo: v2 8c81d550

2016-09-23 11:28

ludovic


Details Diff
(fix) handle 120 EAS status code when message submission fails (fixes 0003774) Affected Issues
0003774
mod - ActiveSync/SOGoActiveSyncDispatcher.m Diff File

Issue History

Date Modified Username Field Change
2016-07-23 19:55 alexeilevinzon New Issue
2016-07-25 02:12 zhb Note Added: 0010539
2016-07-25 02:30 zhb Note Added: 0010540
2016-07-25 07:32 tfu Note Added: 0010542
2016-07-25 07:35 tfu File Added: 3774.diff
2016-09-11 08:18 alexeilevinzon Note Added: 0010640
2016-09-20 19:05 emilio.fonseca Note Added: 0010650
2016-09-20 19:06 ludovic Note Added: 0010651
2016-09-23 15:30 ludovic Changeset attached => sogo master 9bbffe48
2016-09-23 15:30 ludovic Assigned To => ludovic
2016-09-23 15:30 ludovic Resolution open => fixed
2016-09-23 15:32 ludovic Changeset attached => sogo v2 8c81d550
2016-09-23 15:34 ludovic Status new => resolved
2016-09-23 15:34 ludovic Fixed in Version => 3.2.0
2016-10-05 20:05 alexeilevinzon Note Added: 0010722
2016-10-05 20:05 alexeilevinzon Status resolved => feedback
2016-10-05 20:05 alexeilevinzon Resolution fixed => reopened
2016-10-05 20:07 ludovic Note Added: 0010723
2016-10-05 20:07 ludovic Status feedback => resolved
2016-10-05 20:07 ludovic Resolution reopened => fixed