View Issue Details

IDProjectCategoryView StatusLast Update
0005872SOGoActiveSyncpublic2024-10-17 14:18
ReporterSilvanNagl Assigned Toqhivert  
PrioritynormalSeverityminorReproducibilityalways
Status assignedResolutionopen 
Product Version5.8.4 
Summary0005872: high cpu load and some looping behavior of apple devices connecting to sogo / mailcow
Description

https://github.com/mailcow/mailcow-dockerized/issues/5045

Steps To Reproduce

Connect some Apple devices to mailcow.

TagsNo tags attached.

Activities

SilvanNagl

SilvanNagl

2023-09-28 07:13

reporter   ~0017317

2023-09-28-091318_grim.png (113,126 bytes)   
2023-09-28-091318_grim.png (113,126 bytes)   
SilvanNagl

SilvanNagl

2023-09-28 07:49

reporter   ~0017318

For months this problem now eats our resources.
We would really appreciate to find a solution for this.

qhivert

qhivert

2023-09-28 10:00

administrator   ~0017320

Hello,

SilvanNagl

SilvanNagl

2023-10-25 12:50

reporter   ~0017400

Yes, the bug is identically to mentioned comment.

mailcowdockerized-sogo-mailcow-1       | Oct 25 14:49:47 4991662df76e sogod [57]: <0x0x56383afe8b40[SOGoActiveSyncDispatcher]> EAS - request for device 72T5A34GMH0MP16ASAC83JT8UG: <?xml version="1.0"?>
mailcowdockerized-sogo-mailcow-1       | Oct 25 14:49:47 4991662df76e syslog-ng[11]: Error processing log message: <!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/">
mailcowdockerized-sogo-mailcow-1       | <Sync xmlns="AirSync:">
mailcowdockerized-sogo-mailcow-1       |  <Collections>
mailcowdockerized-sogo-mailcow-1       |   <Collection>
mailcowdockerized-sogo-mailcow-1       |    <SyncKey>0</SyncKey>
mailcowdockerized-sogo-mailcow-1       |    <CollectionId>mail%2FShared</CollectionId>
SilvanNagl

SilvanNagl

2023-12-07 11:26

reporter   ~0017491

Any news?

SilvanNagl

SilvanNagl

2023-12-15 09:17

reporter   ~0017504

I really would appreciate some collaboration.
This Problem eats basically 600% CPU on an 8 Core mailcow docker server only because some people connect with their IOS-Devices.
Connecting IOS Devices basically limits down the whole server for everyone causing not only really high power consumption but also killing the user experience.

If there is anything I can provide to speed up the debug process please tell.
If this is not a SoGo bug please also tell.
The mail server runs for months now on maximum load.

https://github.com/mailcow/mailcow-dockerized/issues/5045#issuecomment-1615833182

qhivert

qhivert

2023-12-15 09:54

administrator   ~0017505

Hello,

SilvanNagl

SilvanNagl

2024-01-09 16:12

reporter   ~0017530

For privacy reasons I can not give you the full log but like already mentioned the logs are as follow:

Jan 09 16:53:11 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]: Jan  9 16:53:11 6454ffe7fa29 syslog-ng[10]: Error processing log message: <Ping xmlns="Ping:">
Jan 09 16:53:11 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:  <Status>1</Status>
Jan 09 16:53:11 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]: </Ping>
Jan 09 16:53:11 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]: /HeartbeatInterval>
Jan 09 16:53:11 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:  <Folders>
Jan 09 16:53:11 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:   <Folder>
Jan 09 16:53:11 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:    <Id>mail%2F349e8a121fa0d4611b200000eb6a2ee8</Id>
Jan 09 16:53:11 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:    <Class>Email</Class>
Jan 09 16:53:11 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:   </Folder>
Jan 09 16:53:11 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:   <Folder>
Jan 09 16:53:11 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:    <Id>mail%2F9c212839e01dd76126310000eb6a2ee8</Id>
Jan 09 16:53:11 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:    <Class>Email</Class>
Jan 09 16:53:11 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:   </Folder>
Jan 09 16:53:11 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:   <Folder>
Jan 09 16:53:11 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:    <Id>mail%2Fd05fcc211fa0d4611b200000eb6a2ee8</Id>
Jan 09 16:53:11 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:    <Class>Email</Class>
Jan 09 16:53:11 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:   </Folder>
Jan 09 16:53:11 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:   <Folder>
Jan 09 16:53:11 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:    <Id>vevent%2Fpersonal</Id>
Jan 09 16:53:11 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:    <Class>Calendar</Class>
Jan 09 16:53:11 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:   </Folder>
Jan 09 16:53:11 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:  </Folders>
Jan 09 16:53:11 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]: </Ping>
Jan 09 16:53:11 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]: s>
Jan 09 16:53:11 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:   </Collection>
Jan 09 16:53:11 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:  </Collections>
Jan 09 16:53:11 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]: </Sync>

follwed by the xml content with private data. Than it repeats again with the line "Error processing log message".

Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]: Jan  9 17:05:17 6454ffe7fa29 syslog-ng[10]: Error processing log message: <!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/">
Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]: <Ping xmlns="Ping:">
Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:  <Status>1</Status>
Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]: </Ping>
Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]: ", "mail%2Fdb6b2903b25d7864adf923003b3b2f75")
Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:  '{DAV:}write-content' already exists in DAV permissions table
Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]: s>
Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:   </Folder>
Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:   <Folder>
Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:    <Id>mail%2F9c212839e01dd76126310000eb6a2ee8</Id>
Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:    <Class>Email</Class>
Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:   </Folder>
Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:   <Folder>
Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:    <Id>mail%2Fd05fcc211fa0d4611b200000eb6a2ee8</Id>
Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:    <Class>Email</Class>
Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:   </Folder>
Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:   <Folder>
Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:    <Id>vevent%2Fpersonal</Id>
Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:    <Class>Calendar</Class>
Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:   </Folder>
Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:  </Folders>
Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]: </Ping>
Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]: </Options>
Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:   </Collection>
Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:  </Collections>
Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]: </Sync>
Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]: </Collection>
Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]:  </Collections>
Jan 09 17:05:17 mail-host docker/mailcowdockerized-sogo-mailcow-1[959]: </Sync>
SilvanNagl

SilvanNagl

2024-01-09 16:13

reporter   ~0017531

This repeats probably as fast as the TLS handshake can get.
Again and again, no more error logs in the debug lvl.

SilvanNagl

SilvanNagl

2024-02-14 11:02

reporter   ~0017587

The information needed can be seen in
https://github.com/mailcow/mailcow-dockerized/issues/5045#issuecomment-1912275247

SilvanNagl

SilvanNagl

2024-04-18 13:40

reporter   ~0017711

Any news?

qhivert

qhivert

2024-04-29 12:26

administrator   ~0017717

Hello,
We haven't forget about this but our (Alinto's) hands are full for now.

tfu

tfu

2024-04-30 19:09

reporter   ~0017720

Maybe it helps to find out what request is hammering the server... check logs for fast repeating requests:
POST /SOGo/Microsoft-Server-ActiveSync?User=...&DeviceId=....&DeviceType=...&Cmd=... HTTP/1.1" 200

Maybe you can identify a specific DeviceId= and Cmd= causing the load.

Then it might help to see the some examples of the payload of such repeating requests:
EAS - request for device ...: <?xml
and its
EAS - response for device ....: <?xml

SilvanNagl

SilvanNagl

2024-05-28 09:38

reporter   ~0017741

May 28 11:31:59 mail-host docker/mailcowdockerized-sogo-mailcow-1[971]: May 28 11:31:59 fadc6a0236ba sogod [63]: <0x0x5560b2b0d430[SOGoActiveSyncDispatcher]> EAS - request for device XXX: <?xml version="1.0"?>
May 28 11:31:59 mail-host docker/mailcowdockerized-sogo-mailcow-1[971]: May 28 11:31:59 fadc6a0236ba syslog-ng[10]: Error processing log message: <!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/&quot;>
May 28 11:31:59 mail-host docker/mailcowdockerized-sogo-mailcow-1[971]: <Sync xmlns="AirSync:">
May 28 11:31:59 mail-host docker/mailcowdockerized-sogo-mailcow-1[971]: <Collections>
May 28 11:31:59 mail-host docker/mailcowdockerized-sogo-mailcow-1[971]: <Collection>
May 28 11:31:59 mail-host docker/mailcowdockerized-sogo-mailcow-1[971]: <SyncKey>0</SyncKey>
May 28 11:31:59 mail-host docker/mailcowdockerized-sogo-mailcow-1[971]: <CollectionId>mail%2FShared</CollectionId>
May 28 11:31:59 mail-host docker/mailcowdockerized-sogo-mailcow-1[971]: <Options>
May 28 11:31:59 mail-host docker/mailcowdockerized-sogo-mailcow-1[971]: <FilterType>5</FilterType>
May 28 11:31:59 mail-host docker/mailcowdockerized-sogo-mailcow-1[971]: <MIMETruncation>1</MIMETruncation>
May 28 11:31:59 mail-host docker/mailcowdockerized-sogo-mailcow-1[971]: <MIMESupport>0</MIMESupport>
May 28 11:31:59 mail-host docker/mailcowdockerized-sogo-mailcow-1[971]: <BodyPreference xmlns="AirSyncBase:">
May 28 11:31:59 mail-host docker/mailcowdockerized-sogo-mailcow-1[971]: <Type>1</Type>
May 28 11:31:59 mail-host docker/mailcowdockerized-sogo-mailcow-1[971]: <TruncationSize>500</TruncationSize>
May 28 11:31:59 mail-host docker/mailcowdockerized-sogo-mailcow-1[971]: </BodyPreference>
May 28 11:31:59 mail-host docker/mailcowdockerized-sogo-mailcow-1[971]: </Options>
May 28 11:31:59 mail-host docker/mailcowdockerized-sogo-mailcow-1[971]: </Collection>
May 28 11:31:59 mail-host docker/mailcowdockerized-sogo-mailcow-1[971]: </Collections>
May 28 11:31:59 mail-host docker/mailcowdockerized-sogo-mailcow-1[971]: </Sync>
May 28 11:31:59 mail-host docker/mailcowdockerized-sogo-mailcow-1[971]: <Class>Calendar</Class>
May 28 11:31:59 mail-host docker/mailcowdockerized-sogo-mailcow-1[971]: </Folder>
May 28 11:31:59 mail-host docker/mailcowdockerized-sogo-mailcow-1[971]: </Folders>
May 28 11:31:59 mail-host docker/mailcowdockerized-sogo-mailcow-1[971]: </Ping>

No response this request just comes over and over.

POST /Microsoft-Server-ActiveSync?User=XXX@XXX.com&DeviceId=XXX&DeviceType=iPhone&Cmd=Sync HTTP/2.0" 200 0 "-" "Apple-iPhone16C1/2105.236

This spams over and over again.
With direct disconnect after it than it connects back again and disconnects directly after it.
Again and again and again and again.

SilvanNagl

SilvanNagl

2024-10-17 14:18

reporter   ~0017916

maild on apple phone says:

"Folder item sync task 0x500988280 is using key (null) for folder mail%2FShared"

This aligns to the above error message.

Issue History

Date Modified Username Field Change
2023-09-20 12:09 SilvanNagl New Issue
2023-09-28 07:13 SilvanNagl Note Added: 0017317
2023-09-28 07:13 SilvanNagl File Added: 2023-09-28-091318_grim.png
2023-09-28 07:49 SilvanNagl Note Added: 0017318
2023-09-28 10:00 qhivert Note Added: 0017320
2023-09-28 10:00 qhivert Assigned To => qhivert
2023-09-28 10:00 qhivert Status new => feedback
2023-10-25 12:50 SilvanNagl Note Added: 0017400
2023-10-25 12:50 SilvanNagl Status feedback => assigned
2023-12-07 11:26 SilvanNagl Note Added: 0017491
2023-12-15 09:17 SilvanNagl Note Added: 0017504
2023-12-15 09:54 qhivert Note Added: 0017505
2023-12-15 09:55 qhivert Status assigned => feedback
2024-01-09 16:12 SilvanNagl Note Added: 0017530
2024-01-09 16:12 SilvanNagl Status feedback => assigned
2024-01-09 16:13 SilvanNagl Note Added: 0017531
2024-02-14 11:02 SilvanNagl Note Added: 0017587
2024-04-18 13:40 SilvanNagl Note Added: 0017711
2024-04-29 12:26 qhivert Note Added: 0017717
2024-04-30 19:09 tfu Note Added: 0017720
2024-05-28 09:38 SilvanNagl Note Added: 0017741
2024-10-17 14:18 SilvanNagl Note Added: 0017916