View Issue Details
ID | Project | Category | View Status | Date Submitted | Last Update |
---|---|---|---|---|---|
0005233 | SOGo | ActiveSync | public | 2020-12-10 11:33 | 2021-01-11 17:33 |
Reporter | almo | Assigned To | |||
Priority | normal | Severity | tweak | Reproducibility | N/A |
Status | new | Resolution | open | ||
Platform | [Server] Linux | OS | Debian | OS Version | 8 (Jessie) |
Product Version | 5.0.1 | ||||
Summary | 0005233: Sogo sends emails twice via Outlook | ||||
Description | Hello, I have the problem that when I send an email via Outlook via Active Sync (SOGO), it is sometimes sent twice or even four times. While the sync is running from the outbox, the sent mail is not moved to sent and Outlook does the whole thing again. I've already tried and adjusted everything, but can't find a solution. It's been the same since the upgrade from 4 to 5. | ||||
Additional Information | Debian 9.13 | ||||
Tags | No tags attached. | ||||
Set SOGoEASDebugEnabled = YES. With this parameter set sogo.log will contain more info about the EAS communication between OL and SOGo. |
|
Thanks for pointing out "SOGoEASDebugEnabled = YES". I activated this entry and restarted the whole server and learned the SOGO log. And I wrote a test mail to another server from the server in question, and the mail was sent twice. But I don't find an Error [ERROR] entry in the log at the point where the mail is processed by SOGo. |
|
What is the EAS response to the SendMail request? Have you checked mail. * in /var/log? |
|
Can you please give me an example of what I should be looking for based on the request structure? No, i have only check /var/log/sogo/sogo.log first time |
|
Just look for the string "SendMail" in sogo.log. |
|
The log with the time of the screenshots is attached. I only made the email addresses unrecognizable. sogo_log.txt (24,829 bytes)
Dec 12 15:22:33 sogod [3388]: <0x0x55f80bc48ee0[SOGoCache]> Cache cleanup interval set every 300.000000 seconds Dec 12 15:22:33 sogod [3388]: <0x0x55f80bc48ee0[SOGoCache]> Using host(s) '127.0.0.1' as server(s) Dec 12 15:22:33 sogod [3388]: <0x0x55f80bae5d50[SOGoActiveSyncDispatcher]> EAS - request for device 7C9A0AF94A1A418FA090F026D6BFF3E2: <?xml version="1.0"?> <!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/"> <SendMail xmlns="ComposeMail:"> <ClientId>{242EAA3E-C7D6-44F9-A48A-99C82D36F081}</ClientId> <SaveInSentItems/> <MIME>RnJvbTogIkZhYmlhbiBIYXVuZXIgfCBJQk5LIElUIiA8aXRAaWItbmsuZGU+DQpUbzogIidGYWJpYW4gSGF1bmVyJyIgPGZoQGhhdW5lci1zb2x1dGlvbnMuZGU+DQpTdWJqZWN0OiB0ZXN0DQpEYXRlOiBTYXQsIDEyIERlYyAyMDIwIDE1OjIxOjMyICswMTAwDQpNZXNzYWdlLUlEOiA8MDAxNzAxZDZkMDkyJDNiMTI1YzcwJGIxMzcxNTUwJEBpYi1uay5kZT4NCk1JTUUtVmVyc2lvbjogMS4wDQpDb250ZW50LVR5cGU6IG11bHRpcGFydC9hbHRlcm5hdGl2ZTsNCglib3VuZGFyeT0iLS0tLT1fTmV4dFBhcnRfMDAwXzAwMThfMDFENkQwOUEuOUNEODcyMjAiDQpYLU1haWxlcjogTWljcm9zb2Z0IE91dGxvb2sgMTYuMA0KVGhyZWFkLUluZGV4OiBBZGJRa2hNR1orTGpBenZkVGZDUGJiQUlNTm51amc9PQ0KQ29udGVudC1MYW5ndWFnZTogZGUNCg0KVGhpcyBpcyBhIG11bHRpcGFydCBtZXNzYWdlIGluIE1JTUUgZm9ybWF0Lg0KDQotLS0tLS09X05leHRQYXJ0XzAwMF8wMDE4XzAxRDZEMDlBLjlDRDg3MjIwDQpDb250ZW50LVR5cGU6IHRleHQvcGxhaW47DQoJY2hhcnNldD0idXMtYXNjaWkiDQpDb250ZW50LVRyYW5zZmVyLUVuY29kaW5nOiA3Yml0DQoNCkRhcyBpc3QgZWluZSBnYW56IHdpbGRlIHRlc3QgbWFpbA0KDQogDQoNCiANCg0KDQotLS0tLS09X05leHRQYXJ0XzAwMF8wMDE4XzAxRDZEMDlBLjlDRDg3MjIwDQpDb250ZW50LVR5cGU6IHRleHQvaHRtbDsNCgljaGFyc2V0PSJ1cy1hc2NpaSINCkNvbnRlbnQtVHJhbnNmZXItRW5jb2Rpbmc6IHF1b3RlZC1wcmludGFibGUNCg0KPGh0bWwgeG1sbnM6dj0zRCJ1cm46c2NoZW1hcy1taWNyb3NvZnQtY29tOnZtbCIgPQ0KeG1sbnM6bz0zRCJ1cm46c2NoZW1hcy1taWNyb3NvZnQtY29tOm9mZmljZTpvZmZpY2UiID0NCnhtbG5zOnc9M0QidXJuOnNjaGVtYXMtbWljcm9zb2Z0LWNvbTpvZmZpY2U6d29yZCIgPQ0KeG1sbnM6bT0zRCJodHRwOi8vc2NoZW1hcy5taWNyb3NvZnQuY29tL29mZmljZS8yMDA0LzEyL29tbWwiID0NCnhtbG5zPTNEImh0dHA6Ly93d3cudzMub3JnL1RSL1JFQy1odG1sNDAiPjxoZWFkPjxNRVRBID0NCkhUVFAtRVFVSVY9M0QiQ29udGVudC1UeXBlIiBDT05URU5UPTNEInRleHQvaHRtbDsgPQ0KY2hhcnNldD0zRHVzLWFzY2lpIj48bWV0YSBuYW1lPTNER2VuZXJhdG9yIGNvbnRlbnQ9M0QiTWljcm9zb2Z0IFdvcmQgMTUgPQ0KKGZpbHRlcmVkIG1lZGl1bSkiPjxzdHlsZT48IS0tDQovKiBGb250IERlZmluaXRpb25zICovDQpAZm9udC1mYWNlDQoJe2ZvbnQtZmFtaWx5OiJDYW1icmlhIE1hdGgiOw0KCXBhbm9zZS0xOjIgNCA1IDMgNSA0IDYgMyAyIDQ7fQ0KQGZvbnQtZmFjZQ0KCXtmb250LWZhbWlseTpDYWxpYnJpOw0KCXBhbm9zZS0xOjIgMTUgNSAyIDIgMiA0IDMgMiA0O30NCi8qIFN0eWxlIERlZmluaXRpb25zICovDQpwLk1zb05vcm1hbCwgbGkuTXNvTm9ybWFsLCBkaXYuTXNvTm9ybWFsDQoJe21hcmdpbjowY207DQoJZm9udC1zaXplOjExLjBwdDsNCglmb250LWZhbWlseToiQ2FsaWJyaSIsc2Fucy1zZXJpZjsNCgltc28tZmFyZWFzdC1sYW5ndWFnZTpFTi1VUzt9DQpzcGFuLkUtTWFpbEZvcm1hdHZvcmxhZ2UxNw0KCXttc28tc3R5bGUtdHlwZTpwZXJzb25hbC1jb21wb3NlOw0KCWZvbnQtZmFtaWx5OiJDYWxpYnJpIixzYW5zLXNlcmlmOw0KCWNvbG9yOndpbmRvd3RleHQ7fQ0KLk1zb0NocERlZmF1bHQNCgl7bXNvLXN0eWxlLXR5cGU6ZXhwb3J0LW9ubHk7DQoJZm9udC1mYW1pbHk6IkNhbGlicmkiLHNhbnMtc2VyaWY7DQoJbXNvLWZhcmVhc3QtbGFuZ3VhZ2U6RU4tVVM7fQ0KQHBhZ2UgV29yZFNlY3Rpb24xDQoJe3NpemU6NjEyLjBwdCA3OTIuMHB0Ow0KCW1hcmdpbjo3MC44NXB0IDcwLjg1cHQgMi4wY20gNzAuODVwdDt9DQpkaXYuV29yZFNlY3Rpb24xDQoJe3BhZ2U6V29yZFNlY3Rpb24xO30NCi0tPjwvc3R5bGU+PCEtLVtpZiBndGUgbXNvIDldPjx4bWw+DQo8bzpzaGFwZWRlZmF1bHRzIHY6ZXh0PTNEImVkaXQiIHNwaWRtYXg9M0QiMTAyNiIgLz4NCjwveG1sPjwhW2VuZGlmXS0tPjwhLS1baWYgZ3RlIG1zbyA5XT48eG1sPg0KPG86c2hhcGVsYXlvdXQgdjpleHQ9M0QiZWRpdCI+DQo8bzppZG1hcCB2OmV4dD0zRCJlZGl0IiBkYXRhPTNEIjEiIC8+DQo8L286c2hhcGVsYXlvdXQ+PC94bWw+PCFbZW5kaWZdLS0+PC9oZWFkPjxib2R5IGxhbmc9M0RERSA9DQpsaW5rPTNEIiMwNTYzQzEiIHZsaW5rPTNEIiM5NTRGNzIiIHN0eWxlPTNEJ3dvcmQtd3JhcDpicmVhay13b3JkJz48ZGl2ID0NCmNsYXNzPTNEV29yZFNlY3Rpb24xPjxwIGNsYXNzPTNETXNvTm9ybWFsPkRhcyBpc3QgZWluZSBnYW56IHdpbGRlIHRlc3QgPQ0KbWFpbDxvOnA+PC9vOnA+PC9wPjxwIGNsYXNzPTNETXNvTm9ybWFsPjxvOnA+Jm5ic3A7PC9vOnA+PC9wPjxwID0NCmNsYXNzPTNETXNvTm9ybWFsPjxvOnA+Jm5ic3A7PC9vOnA+PC9wPjwvZGl2PjwvYm9keT48L2h0bWw+DQotLS0tLS09X05leHRQYXJ0XzAwMF8wMDE4XzAxRDZEMDlBLjlDRDg3MjIwLS0NCg==</MIME> </SendMail> 2020-12-12 15:22:33.198 sogod[3388:3388] SMTP: STARTTLS successfully performed Dec 12 15:22:33 sogod [3389]: [WARN] <0x0x55f80bf93c50[SOGoWebDAVAclManager]> entry '{DAV:}write' already exists in DAV permissions table Dec 12 15:22:33 sogod [3389]: [WARN] <0x0x55f80bf93c50[SOGoWebDAVAclManager]> entry '{DAV:}write-properties' already exists in DAV permissions table Dec 12 15:22:33 sogod [3389]: [WARN] <0x0x55f80bf93c50[SOGoWebDAVAclManager]> entry '{DAV:}write-content' already exists in DAV permissions table Dec 12 15:22:33 sogod [3388]: 79.250.251.121 "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=SendMail&User=it@ib-nk.de&DeviceId=7C9A0AF94A1A418FA090F026D6BFF3E2&DeviceType=WindowsOutlook15 HTTP/1.1" 200 0/2571 0.521 - - 6M - 11 Dec 12 15:22:33 sogod [3389]: <0x0x55f80be94a20[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null) Dec 12 15:22:34 sogod [3389]: <0x0x55f80baf6c80[SOGoActiveSyncDispatcher]> EAS - sortedBySequence (918) - lastObject: 924-956 Dec 12 15:22:34 sogod [3389]: <0x0x55f80baf6c80[SOGoActiveSyncDispatcher]> EAS - allCacheObjects (2) - lastObject: 925-957 Dec 12 15:22:34 sogod [3389]: <0x0x55f80baf6c80[SOGoActiveSyncDispatcher]> EAS - found in cache: 0 k = 0 Dec 12 15:22:34 sogod [3389]: <0x0x55f80baf6c80[SOGoActiveSyncDispatcher]> EAS - Dealing with cacheObject: 924-956 Dec 12 15:22:34 sogod [3389]: <0x0x55f80baf6c80[SOGoActiveSyncDispatcher]> EAS - Dealing with cacheObject: 925-957 Dec 12 15:22:34 sogod [3389]: <0x0x55f80baf6c80[SOGoActiveSyncDispatcher]> EAS - ADD! Dec 12 15:22:34 sogod [3389]: <0x0x55f80baf6c80[SOGoActiveSyncDispatcher]> EAS - first uid added 925 Dec 12 15:22:34 sogod [3389]: <0x0x55f80baf6c80[SOGoActiveSyncDispatcher]> Change detected during Sync, we push the content. Dec 12 15:22:34 sogod [3389]: <0x0x55f80baf6c80[SOGoActiveSyncDispatcher]> EAS - response for device 7C9A0AF94A1A418FA090F026D6BFF3E2: <?xml version="1.0"?> <!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/"> <Sync xmlns="AirSync:"> <Collections> <Collection> <Class>Email</Class> <SyncKey>966-2022</SyncKey> <CollectionId>mail%2Fbc70d32816b8655af0040000d36fe14d</CollectionId> <Status>1</Status> </Collection> <Collection> <Class>Calendar</Class> <SyncKey>1518180702</SyncKey> <CollectionId>vevent%2Fpersonal</CollectionId> <Status>1</Status> </Collection> <Collection> <Class>Contacts</Class> <SyncKey>1552598017</SyncKey> <CollectionId>vcard%2Fpersonal</CollectionId> <Status>1</Status> </Collection> <Collection> <Class>Email</Class> <SyncKey>420-970</SyncKey> <CollectionId>mail%2F3baca31526c9725ad0080000d36fe14d</CollectionId> <Status>1</Status> </Collection> <Collection> <Class>Email</Class> <SyncKey>925-957</SyncKey> <CollectionId>mail%2Fb970d32816b8655af0040000d36fe14d</CollectionId> <Status>1</Status> <Commands> <Add> <ServerId>925</ServerId> <ApplicationData> <To xmlns="Email:">"'Fabian Hauner'" <fh@xxxxx.de></To> <DisplayTo xmlns="Email:">'Fabian Hauner'</DisplayTo> <From xmlns="Email:">"Fabian Hauner | IBNK IT" <it@xxxxxx.de></From> <Subject xmlns="Email:">test</Subject> <ThreadTopic xmlns="Email:">test</ThreadTopic> <DateReceived xmlns="Email:">2020-12-12T14:21:32.000Z</DateReceived> <Importance xmlns="Email:">1</Importance> <Read xmlns="Email:">1</Read> <MessageClass xmlns="Email:">IPM.Note</MessageClass> <ContentClass xmlns="Email:">urn:content-classes:message</ContentClass> <InternetCPID xmlns="Email:">65001</InternetCPID> <Body xmlns="AirSyncBase:"> <Type>4</Type> <Truncated>0</Truncated> <Preview/> <Data>From: "Fabian Hauner | IBNK IT" <it@xxxxx.de> To: "'Fabian Hauner'" <fh@xxxxxx.de> Subject: test Date: Sat, 12 Dec 2020 15:21:32 +0100 Message-ID: <001701d6d092$3b125c70$b1371550$@xxxxxxxx.de> MIME-Version: 1.0 Content-Type: multipart/alternative; boundary="----=_NextPart_000_0018_01D6D09A.9CD87220" X-Mailer: Microsoft Outlook 16.0 Thread-Index: AdbQkhMGZ+LjAzvdTfCPbbAIMNnujg== Content-Language: de This is a multipart message in MIME format. ------=_NextPart_000_0018_01D6D09A.9CD87220 Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit Das ist eine ganz wilde test mail ------=_NextPart_000_0018_01D6D09A.9CD87220 Content-Type: text/html; charset="us-ascii" Content-Transfer-Encoding: quoted-printable <html xmlns:v=3D"urn:schemas-microsoft-com:vml" = xmlns:o=3D"urn:schemas-microsoft-com:office:office" = xmlns:w=3D"urn:schemas-microsoft-com:office:word" = xmlns:m=3D"http://schemas.microsoft.com/office/2004/12/omml" = xmlns=3D"http://www.w3.org/TR/REC-html40"><head><META = HTTP-EQUIV=3D"Content-Type" CONTENT=3D"text/html; = charset=3Dus-ascii"><meta name=3DGenerator content=3D"Microsoft Word 15 = (filtered medium)"><style><!-- /* Font Definitions */ @font-face {font-family:"Cambria Math"; panose-1:2 4 5 3 5 4 6 3 2 4;} @font-face {font-family:Calibri; panose-1:2 15 5 2 2 2 4 3 2 4;} /* Style Definitions */ p.MsoNormal, li.MsoNormal, div.MsoNormal {margin:0cm; font-size:11.0pt; font-family:"Calibri",sans-serif; mso-fareast-language:EN-US;} span.E-MailFormatvorlage17 {mso-style-type:personal-compose; font-family:"Calibri",sans-serif; color:windowtext;} .MsoChpDefault {mso-style-type:export-only; font-family:"Calibri",sans-serif; mso-fareast-language:EN-US;} @page WordSection1 {size:612.0pt 792.0pt; margin:70.85pt 70.85pt 2.0cm 70.85pt;} div.WordSection1 {page:WordSection1;} --></style><!--[if gte mso 9]><xml> <o:shapedefaults v:ext=3D"edit" spidmax=3D"1026" /> </xml><![endif]--><!--[if gte mso 9]><xml> <o:shapelayout v:ext=3D"edit"> <o:idmap v:ext=3D"edit" data=3D"1" /> </o:shapelayout></xml><![endif]--></head><body lang=3DDE = link=3D"#0563C1" vlink=3D"#954F72" style=3D'word-wrap:break-word'><div = class=3DWordSection1><p class=3DMsoNormal>Das ist eine ganz wilde test = mail<o:p></o:p></p><p class=3DMsoNormal><o:p>&nbsp;</o:p></p><p = class=3DMsoNormal><o:p>&nbsp;</o:p></p></div></body></html> ------=_NextPart_000_0018_01D6D09A.9CD87220--</Data> <EstimatedDataSize>3307</EstimatedDataSize> </Body> <Flag xmlns="Email:"> <FlagStatus>0</FlagStatus> </Flag> <Categories xmlns="Email:"/> <ConversationId xmlns="Email2:">PDAwMTcwMWQ2ZDA5MiQzYjEyNWM3MCRiMTM3MTU1MCRAaWItbmsuZGU+</ConversationId> <LastVerbExecuted xmlns="Email2:">0</LastVerbExecuted> <NativeBodyType xmlns="AirSyncBase:">1</NativeBodyType> </ApplicationData> </Add> </Commands> </Collection> <Collection> <Class>Tasks</Class> <SyncKey>1518180702</SyncKey> <CollectionId>vtodo%2Fpersonal</CollectionId> <Status>1</Status> </Collection> <Collection> <Class>Email</Class> <SyncKey>2-2</SyncKey> <CollectionId>mail%2F1f2683324631735a13280000d36fe14d</CollectionId> <Status>1</Status> </Collection> <Collection> <Class>Email</Class> <SyncKey>4-2</SyncKey> <CollectionId>mail%2F50f63a2edc253f5be31c0000d36fe14d</CollectionId> <Status>1</Status> </Collection> <Collection> <Class>Email</Class> <SyncKey>1-1</SyncKey> <CollectionId>mail%2Fbb70d32816b8655af0040000d36fe14d</CollectionId> <Status>1</Status> </Collection> <Collection> <Class>Email</Class> <SyncKey>150-218</SyncKey> <CollectionId>mail%2Fe745fa02a5b2655aee030000d36fe14d</CollectionId> <Status>1</Status> </Collection> <Collection> <Class>Calendar</Class> <SyncKey>1582141181</SyncKey> <CollectionId>vevent%2Finfo_A_ib-nk_D_de_88D-5A76E780-1-E856AB0</CollectionId> <Status>1</Status> </Collection> </Collections> </Sync> Dec 12 15:22:34 sogod [3389]: 79.250.251.121 "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=it@ib-nk.de&DeviceId=7C9A0AF94A1A418FA090F026D6BFF3E2&DeviceType=WindowsOutlook15 HTTP/1.1" 200 3573/1109 1.568 - - 12M - 12 Dec 12 15:22:35 sogod [3389]: <0x0x55f80b88c150[SOGoActiveSyncDispatcher]> EAS - request for device 7C9A0AF94A1A418FA090F026D6BFF3E2: <?xml version="1.0"?> <!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/"> <Sync xmlns="AirSync:"> <Collections> <Collection> <SyncKey>966-2022</SyncKey> <CollectionId>mail%2Fbc70d32816b8655af0040000d36fe14d</CollectionId> <DeletesAsMoves>0</DeletesAsMoves> <WindowSize>512</WindowSize> <Options> <FilterType>0</FilterType> <MIMESupport>2</MIMESupport> <MIMETruncation>8</MIMETruncation> <BodyPreference xmlns="AirSyncBase:"> <Type>4</Type> <AllOrNone>1</AllOrNone> </BodyPreference> </Options> </Collection> <Collection> <SyncKey>1518180702</SyncKey> <CollectionId>vevent%2Fpersonal</CollectionId> <DeletesAsMoves>0</DeletesAsMoves> <WindowSize>512</WindowSize> <Options> <FilterType>0</FilterType> <BodyPreference xmlns="AirSyncBase:"> <Type>1</Type> <AllOrNone>1</AllOrNone> </BodyPreference> </Options> </Collection> <Collection> <SyncKey>1552598017</SyncKey> <CollectionId>vcard%2Fpersonal</CollectionId> <DeletesAsMoves>0</DeletesAsMoves> <WindowSize>512</WindowSize> <Options> <FilterType>0</FilterType> <BodyPreference xmlns="AirSyncBase:"> <Type>1</Type> <AllOrNone>1</AllOrNone> </BodyPreference> </Options> </Collection> <Collection> <SyncKey>420-970</SyncKey> <CollectionId>mail%2F3baca31526c9725ad0080000d36fe14d</CollectionId> <DeletesAsMoves>0</DeletesAsMoves> <WindowSize>512</WindowSize> <Options> <FilterType>0</FilterType> <MIMESupport>2</MIMESupport> <MIMETruncation>8</MIMETruncation> <BodyPreference xmlns="AirSyncBase:"> <Type>4</Type> <AllOrNone>1</AllOrNone> </BodyPreference> </Options> </Collection> <Collection> <SyncKey>925-957</SyncKey> <CollectionId>mail%2Fb970d32816b8655af0040000d36fe14d</CollectionId> <DeletesAsMoves>0</DeletesAsMoves> <WindowSize>512</WindowSize> <Options> <FilterType>0</FilterType> <MIMESupport>2</MIMESupport> <MIMETruncation>8</MIMETruncation> <BodyPreference xmlns="AirSyncBase:"> <Type>4</Type> <AllOrNone>1</AllOrNone> </BodyPreference> </Options> </Collection> <Collection> <SyncKey>1518180702</SyncKey> <CollectionId>vtodo%2Fpersonal</CollectionId> <DeletesAsMoves>0</DeletesAsMoves> <WindowSize>512</WindowSize> <Options> <FilterType>0</FilterType> <BodyPreference xmlns="AirSyncBase:"> <Type>1</Type> <AllOrNone>1</AllOrNone> </BodyPreference> </Options> </Collection> <Collection> <SyncKey>2-2</SyncKey> <CollectionId>mail%2F1f2683324631735a13280000d36fe14d</CollectionId> <DeletesAsMoves>0</DeletesAsMoves> <WindowSize>512</WindowSize> <Options> <FilterType>0</FilterType> <MIMESupport>2</MIMESupport> <MIMETruncation>8</MIMETruncation> <BodyPreference xmlns="AirSyncBase:"> <Type>4</Type> <AllOrNone>1</AllOrNone> </BodyPreference> </Options> </Collection> <Collection> <SyncKey>4-2</SyncKey> <CollectionId>mail%2F50f63a2edc253f5be31c0000d36fe14d</CollectionId> <DeletesAsMoves>0</DeletesAsMoves> <WindowSize>512</WindowSize> <Options> <FilterType>0</FilterType> <MIMESupport>2</MIMESupport> <MIMETruncation>8</MIMETruncation> <BodyPreference xmlns="AirSyncBase:"> <Type>4</Type> <AllOrNone>1</AllOrNone> </BodyPreference> </Options> </Collection> <Collection> <SyncKey>(null)-(null)</SyncKey> <CollectionId>mail%2FShared</CollectionId> <DeletesAsMoves>0</DeletesAsMoves> <WindowSize>512</WindowSize> <Options> <FilterType>0</FilterType> <MIMESupport>2</MIMESupport> <MIMETruncation>8</MIMETruncation> <BodyPreference xmlns="AirSyncBase:"> <Type>4</Type> <AllOrNone>1</AllOrNone> </BodyPreference> </Options> </Collection> <Collection> <SyncKey>1-1</SyncKey> <CollectionId>mail%2Fbb70d32816b8655af0040000d36fe14d</CollectionId> <DeletesAsMoves>0</DeletesAsMoves> <WindowSize>512</WindowSize> <Options> <FilterType>0</FilterType> <MIMESupport>2</MIMESupport> <MIMETruncation>8</MIMETruncation> <BodyPreference xmlns="AirSyncBase:"> <Type>4</Type> <AllOrNone>1</AllOrNone> </BodyPreference> </Options> </Collection> <Collection> <SyncKey>150-218</SyncKey> <CollectionId>mail%2Fe745fa02a5b2655aee030000d36fe14d</CollectionId> <DeletesAsMoves>0</DeletesAsMoves> <WindowSize>512</WindowSize> <Options> <FilterType>0</FilterType> <MIMESupport>2</MIMESupport> <MIMETruncation>8</MIMETruncation> <BodyPreference xmlns="AirSyncBase:"> <Type>4</Type> <AllOrNone>1</AllOrNone> </BodyPreference> </Options> </Collection> <Collection> <SyncKey>1582141181</SyncKey> <CollectionId>vevent%2Finfo_A_ib-nk_D_de_88D-5A76E780-1-E856AB0</CollectionId> <DeletesAsMoves>0</DeletesAsMoves> <WindowSize>512</WindowSize> <Options> <FilterType>0</FilterType> <BodyPreference xmlns="AirSyncBase:"> <Type>1</Type> <AllOrNone>1</AllOrNone> </BodyPreference> </Options> </Collection> </Collections> <WindowSize>16</WindowSize> </Sync> Dec 12 15:22:36 sogod [3389]: <0x0x55f80be75ce0[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null) Dec 12 15:22:36 sogod [3389]: <0x0x55f80b88c150[SOGoActiveSyncDispatcher]> EAS - sortedBySequence (919) - lastObject: 925-957 Dec 12 15:22:36 sogod [3389]: <0x0x55f80b88c150[SOGoActiveSyncDispatcher]> EAS - allCacheObjects (1) - lastObject: 925-957 Dec 12 15:22:36 sogod [3389]: <0x0x55f80b88c150[SOGoActiveSyncDispatcher]> EAS - found in cache: 0 k = 0 Dec 12 15:22:36 sogod [3389]: <0x0x55f80b88c150[SOGoActiveSyncDispatcher]> EAS - Dealing with cacheObject: 925-957 Dec 12 15:22:36 sogod [3389]: <0x0x55f80b88c150[SOGoActiveSyncDispatcher]> Change detected during Sync, we push the content. Dec 12 15:22:36 sogod [3389]: <0x0x55f80b88c150[SOGoActiveSyncDispatcher]> EAS - response for device 7C9A0AF94A1A418FA090F026D6BFF3E2: <?xml version="1.0"?> <!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/"> <Sync xmlns="AirSync:"> <Collections> <Collection> <Class>Email</Class> <SyncKey>966-2022</SyncKey> <CollectionId>mail%2Fbc70d32816b8655af0040000d36fe14d</CollectionId> <Status>1</Status> </Collection> <Collection> <Class>Calendar</Class> <SyncKey>1518180702</SyncKey> <CollectionId>vevent%2Fpersonal</CollectionId> <Status>1</Status> </Collection> <Collection> <Class>Contacts</Class> <SyncKey>1552598017</SyncKey> <CollectionId>vcard%2Fpersonal</CollectionId> <Status>1</Status> </Collection> <Collection> <Class>Email</Class> <SyncKey>420-970</SyncKey> <CollectionId>mail%2F3baca31526c9725ad0080000d36fe14d</CollectionId> <Status>1</Status> </Collection> <Collection> <Class>Email</Class> <SyncKey>926-957</SyncKey> <CollectionId>mail%2Fb970d32816b8655af0040000d36fe14d</CollectionId> <Status>1</Status> </Collection> <Collection> <Class>Tasks</Class> <SyncKey>1518180702</SyncKey> <CollectionId>vtodo%2Fpersonal</CollectionId> <Status>1</Status> </Collection> <Collection> <Class>Email</Class> <SyncKey>2-2</SyncKey> <CollectionId>mail%2F1f2683324631735a13280000d36fe14d</CollectionId> <Status>1</Status> </Collection> <Collection> <Class>Email</Class> <SyncKey>4-2</SyncKey> <CollectionId>mail%2F50f63a2edc253f5be31c0000d36fe14d</CollectionId> <Status>1</Status> </Collection> <Collection> <Class>Email</Class> <SyncKey>1-1</SyncKey> <CollectionId>mail%2Fbb70d32816b8655af0040000d36fe14d</CollectionId> <Status>1</Status> </Collection> <Collection> <Class>Email</Class> <SyncKey>150-218</SyncKey> <CollectionId>mail%2Fe745fa02a5b2655aee030000d36fe14d</CollectionId> <Status>1</Status> </Collection> <Collection> <Class>Calendar</Class> <SyncKey>1582141181</SyncKey> <CollectionId>vevent%2Finfo_A_ib-nk_D_de_88D-5A76E780-1-E856AB0</CollectionId> <Status>1</Status> </Collection> </Collections> </Sync> Dec 12 15:22:36 sogod [3389]: 79.250.251.121 "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=it@ib-nk.de&DeviceId=7C9A0AF94A1A418FA090F026D6BFF3E2&DeviceType=WindowsOutlook15 HTTP/1.1" 200 730/1109 1.459 - - 0 - 12 Dec 12 15:22:38 sogod [654]: [WARN] <0x0x55f80ba81e60[WOWatchDogChild]> safety belt -- sending KILL signal to pid 2748 Dec 12 15:22:39 sogod [654]: <0x0x55f80ba81e60[WOWatchDogChild]> child 2748 exited Dec 12 15:22:39 sogod [654]: <0x0x55f80ba81e60[WOWatchDogChild]> (terminated due to signal 9) Dec 12 15:22:39 sogod [3389]: <0x0x55f80b84a130[SOGoActiveSyncDispatcher]> EAS - request for device 7C9A0AF94A1A418FA090F026D6BFF3E2: <?xml version="1.0"?> <!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/"> <Ping xmlns="Ping:"> <HeartbeatInterval>3540</HeartbeatInterval> <Folders> <Folder> <Id>mail%2Fbc70d32816b8655af0040000d36fe14d</Id> <Class>Email</Class> </Folder> <Folder> <Id>vevent%2Fpersonal</Id> <Class>Calendar</Class> </Folder> <Folder> <Id>vcard%2Fpersonal</Id> <Class>Contacts</Class> </Folder> <Folder> <Id>mail%2F3baca31526c9725ad0080000d36fe14d</Id> <Class>Email</Class> </Folder> <Folder> <Id>mail%2Fb970d32816b8655af0040000d36fe14d</Id> <Class>Email</Class> </Folder> <Folder> <Id>vtodo%2Fpersonal</Id> <Class>Tasks</Class> </Folder> <Folder> <Id>mail%2F1f2683324631735a13280000d36fe14d</Id> <Class>Email</Class> </Folder> <Folder> <Id>mail%2F50f63a2edc253f5be31c0000d36fe14d</Id> <Class>Email</Class> </Folder> <Folder> <Id>mail%2FShared</Id> <Class>Email</Class> </Folder> <Folder> <Id>mail%2Fbb70d32816b8655af0040000d36fe14d</Id> <Class>Email</Class> </Folder> <Folder> <Id>mail%2Fe745fa02a5b2655aee030000d36fe14d</Id> <Class>Email</Class> </Folder> <Folder> <Id>vevent%2Finfo_A_ib-nk_D_de_88D-5A76E780-1-E856AB0</Id> <Class>Calendar</Class> </Folder> </Folders> </Ping> Dec 12 15:22:39 sogod [654]: <0x0x55f80ba4a8b0[WOWatchDog]> child spawned with pid 3407 Dec 12 15:22:39 sogod [3407]: <0x0x55f80bb32690[WOHttpAdaptor]> notified the watchdog that we are ready Dec 12 15:22:40 sogod [3389]: <0x0x55f80b84a130[SOGoActiveSyncDispatcher]> Sleeping 30 seconds while detecting changes for user it@ib-nk.de in Ping... Dec 12 15:22:49 sogod [3407]: <0x0x55f80bc315f0[SOGoCache]> Cache cleanup interval set every 300.000000 seconds Dec 12 15:22:49 sogod [3407]: <0x0x55f80bc315f0[SOGoCache]> Using host(s) '127.0.0.1' as server(s) Dec 12 15:22:49 sogod [3407]: <0x0x55f80b87f520[SOGoActiveSyncDispatcher]> EAS - request for device SEC19E4196878C70: <?xml version="1.0"?> <!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/"> <Ping xmlns="Ping:"> <HeartbeatInterval>880</HeartbeatInterval> <Folders> <Folder> <Id>vcard%2Fpersonal</Id> <Class>Contacts</Class> </Folder> <Folder> <Id>vtodo%2Fpersonal</Id> <Class>Tasks</Class> </Folder> <Folder> <Id>mail%2Fa3bfee203e63755a9e280000d36fe14d</Id> <Class>Email</Class> </Folder> <Folder> <Id>mail%2Fae8a9b2cc772775a20390000d36fe14d</Id> <Class>Email</Class> </Folder> <Folder> <Id>vtodo%2Finfo_A_ib-nk_D_de_88D-5A76E780-1-E856AB0</Id> <Class>Tasks</Class> </Folder> <Folder> <Id>vevent%2Finfo_A_ib-nk_D_de_88D-5A76E780-1-E856AB0</Id> <Class>Calendar</Class> </Folder> <Folder> <Id>vevent%2Fpersonal</Id> <Class>Calendar</Class> </Folder> </Folders> </Ping> |
|
In the log you provided I see only one SendMail-request. |
|
I have same problem. One process get stucked, consume 100% of one core and for some time outlook is not synchronized. After while it gets unstucked and send email second time. I am unable to find anything interesting in log, event when EAS debug enabled. I dont want to put it here, becaouse of lots of personal stuff. |
|
and also - it started when upgrade to sogo 5 |
|
@hlava whats your System? I don't have the problem on my other Sogo 5 system under Debian 10. |
|
It does not happen offten. Ones a week or something. Thats why it is difficult to find the problem. I am near to to prepare fresh server for mails. It happens to all mailboxes. We dont have many of them, about 20 or something like that, but everyone uses activesync. And system is Ubuntu 18.04.5 LTS. Interesting is, that when PID proces stuck, and I stop sogod, it wont killed that stucked process. In log is - forcing to stop that, but no success. I have to do kill -9 to really kill him. But it is quite old installation with iredadmin, I have done lots of updates since, but I am curious, that @almo has same problem since upgrade to sogo 5. (sorry for my english) |
|
214 / 5000 |
|
It would help to see a complete set of log-files starting with the time the mail was sent for the first time (i.e. starting with the SendMail-Request). If Outlook is initiating the send of the duplicate mail I'd expect to find another SendMail-Request.
Following sed (or a similar one) could strip some sensitive data: Note: The SendMail request contains a base64 encoded version of the mail. |
|
I have Push the Orginal Log from Screenshot from 12.12.2020 on my CloudServer and Shared it for you. I have Clean the sogo.log an reboot the Server and have send one Mail from me to an other to me. After this i have grep the log. Logs -> https://groot.sys24.org/cloud/index.php/s/tjjzcWkdja5HzX2 And I anonymized the current SoGo Log and also filed it. I hope to find something there |
|
Dec 17 11:04:18 sogod [12188]: <0x0x564a269fb060[SOGoActiveSyncDispatcher]> EAS - request for device D4C7E2162F864EA8A9AFF5DD50957B48: <?xml version="1.0"?> .... 2020-12-17 11:04:19.045 sogod[12188:12188] SMTP: STARTTLS successfully performed .... Dec 17 11:05:18 sogod [21265]: [WARN] <0x0x564a26144cb0[WOWatchDogChild]> safety belt -- sending KILL signal to pid 12188 ... Dec 17 11:05:19 sogod [12475]: 24.134.92.57 "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=SendMail&User=lachenmaier@ib-nk.de&DeviceId=D4C7E2162F864EA8A9AFF5DD50957B48&DeviceType=WindowsOutlook15 HTTP/1.1" 200 0/3284 0.550 - - 288K - 12What do you get in the smtp-server logs around the time of above log excerpt? |
|
What do you get in the smtp-server logs around the time of above log excerpt? I also put sogo.conf in the cloud, and censored the passwords with ***** |
|
The smtp.log shows 2 successfully send attempts. According to above info from sogo.log the first mail is sent a sogod process with PID 12188. This process sends the mail successfully but doens't respond back to OL. 1) Check whether SOGO and SOPE have the same version. |
|
The smtp.log shows 2 successfully send attempts. According to above info from sogo.log the first mail is sent by sogod process with PID 12188. This process sends the mail successfully but doens't respond back to OL. Can you please reproduce the problem and produce back trace as described here: https://sogo.nu/support/faq/how-do-i-debug-sogo.html |
|
Currently I have success with little of tuning sogo config (timout, limit etc.). A Also give higher memeory limit to PID and add cpus and memory to vm. (750MB per pid, 20PIDS, 10 Cpus, 25GB RAM). It is quite a lot, but seems to successfuly remove problem with stucked pid and resending emails. I will let you know after longer period. |
|
@tfu -> How can I check the sope version? My Sogo Version is (5.0.1.20201219-1) sogo-activesync (5.0.1.20201219-1) @hlava -> Can you please provide your customized config anonymously somehow? |
|
I noticed that when I attach a PDF with 10 MB to an email it always comes out twice or even 8 times. |
|
|
|
Here is one link returned on a quick search: https://www.cyberciti.biz/faq/find-out-if-package-is-installed-in-linux/ |
|
Thank you for your answer. I executed the command and got the following return. A query for sope or the other sope modules comes to nothing. So how can I determine whether the "sope" is properly installed? |
|
Addendum, for completeness dpkg-query -l 'sope*' |
|
|
|
As sorry as I am, I made the adjustments from https://sogo.nu/files/docs/SOGoInstallationGuide.html#_microsoft_enterprise_activesync_tuning. And the problem doesn't get better and continues |
|
When i set parameters as recomended in guide, it was much worse. I had to make fresh install of everything to solve the problem. Now it seems working fine. |
|
hlava, that's not good news at all. Sure, a Fresh Install will probably run really well. But I don't want to re-import 350 GB of mail ... I'm wondering if upgrading from Debian 9.13 to 10.7 will solve my problem, or just make it worse |
|
i am not sure. I have vmail directory on NAS, and import ldap is question of couple of hours. So for me it was not a problem. And after all, it was really old instalation as well. Users seems to be happy right now again :) |
|
Well, for me it is a VPS in a data center. The entire life of a small company runs there. So website & mail. So reinstall has to be planned and ready by working hours ... So I'm not so happy to have to do it all over again |
|
Date Modified | Username | Field | Change |
---|---|---|---|
2020-12-10 11:33 | almo | New Issue | |
2020-12-12 07:54 | tfu | Note Added: 0014990 | |
2020-12-12 14:38 | almo | Note Added: 0014991 | |
2020-12-12 14:38 | almo | File Added: error.jpg | |
2020-12-12 14:38 | almo | File Added: Outlook send.JPG | |
2020-12-12 17:05 | tfu | Note Added: 0014992 | |
2020-12-12 17:14 | almo | Note Added: 0014993 | |
2020-12-14 12:56 | tfu | Note Added: 0014995 | |
2020-12-14 17:17 | almo | Note Added: 0014996 | |
2020-12-14 17:17 | almo | File Added: sogo_log.txt | |
2020-12-14 20:59 | tfu | Note Added: 0014997 | |
2020-12-14 21:47 | hlava | Note Added: 0014998 | |
2020-12-14 21:48 | hlava | Note Added: 0014999 | |
2020-12-15 06:54 | almo | Note Added: 0015000 | |
2020-12-15 09:01 | hlava | Note Added: 0015001 | |
2020-12-16 15:34 | almo | Note Added: 0015002 | |
2020-12-17 09:12 | tfu | Note Added: 0015003 | |
2020-12-17 10:16 | almo | Note Added: 0015004 | |
2020-12-17 16:37 | tfu | Note Added: 0015005 | |
2020-12-17 17:36 | almo | Note Added: 0015006 | |
2020-12-18 11:08 | tfu | Note Added: 0015007 | |
2020-12-18 11:10 | tfu | Note Added: 0015008 | |
2020-12-18 13:05 | hlava | Note Added: 0015009 | |
2020-12-19 08:01 | almo | Note Added: 0015010 | |
2020-12-21 08:13 | almo | Note Added: 0015011 | |
2021-01-02 14:14 | almo | Note Added: 0015012 | |
2021-01-02 17:23 | tfu | Note Added: 0015013 | |
2021-01-02 18:22 | almo | Note Added: 0015014 | |
2021-01-02 18:28 | almo | Note Added: 0015015 | |
2021-01-02 20:02 | tfu | Note Added: 0015016 | |
2021-01-11 13:25 | almo | Note Added: 0015022 | |
2021-01-11 16:43 | hlava | Note Added: 0015023 | |
2021-01-11 17:27 | almo | Note Added: 0015024 | |
2021-01-11 17:29 | hlava | Note Added: 0015025 | |
2021-01-11 17:33 | almo | Note Added: 0015026 |