Mailcow-dockerized: Timeout activesync

[Happyfeet01]

Describe the bug, try to make it reproducible
The Emails sync to the device only when i open the mailclient in iOS. Windows Client works good.

System information and quick debugging
General logs:
Nginx Log:
2019/05/13 11:25:16 [error] 19178#19178: *2770 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 2003:f9:570d:d700:15ad:6490:xxxxa, server: mail.mail.domain.tld, request: "POST /Microsoft-Server-ActiveSync?jQAHBBC5KA1Wkp/fDGN0EqhqG2XOBAAAAAALV2luZG93c01haWw= HTTP/1.1", upstream: "http://127.0.0.1:8080/Microsoft-Server-ActiveSync?jQAHBBC5KA1Wkp/fDGN0EqhqG2XOBAAAAAALV2luZG93c01haWw=", host: "mail.domain.tld"

Further information (where applicable):

• Your OS (is Apparmor or SELinux active?)
  Ubuntu 18.04, Apparmor is active
• Your virtualization technology (KVM/QEMU, Xen, VMware, VirtualBox etc.)
  Docker
• Your server/VM specifications (Memory, CPU Cores)
  *-memory
  description: System memory
  physical id: 0
  size: 15GiB
  *-cpu
  product: Intel(R) Core(TM) i7-2600 CPU @ 3.40GHz
  vendor: Intel Corp.
  physical id: 1
  bus info: cpu@0
  size: 2375MHz
  capacity: 3800MHz
  
  
  
  • 3 TB HDD Storage
  
  

• Don't try to run mailcow on a Synology or QNAP NAS, do you?
  No
• Docker and Docker Compose versions
  Client:
  Version: 18.09.2
  API version: 1.39
  Go version: go1.10.4
  Git commit: 6247962
  Built: Tue Feb 26 23:52:23 2019
  OS/Arch: linux/amd64
  Experimental: false

[andryyy]

Hi, Increase the SOGo worker count in data/conf/sogo/sogo.conf (it is 20
by default). Track your RAM.

------ Originalnachricht ------
Von: "Happyfeet01" [e-mail]
An: "mailcow/mailcow-dockerized" [e-mail]
Cc: "Subscribed" [e-mail]
Gesendet: 13.05.2019 11:45:10
Betreff: [mailcow/mailcow-dockerized] Timeout activesync (#2599)

Describe the bug, try to make it reproducible
The Emails sync to the device only when i open the mailclient in iOS.
Windows Client works good.

System information and quick debugging
General logs:
Nginx Log:
2019/05/13 11:25:16 [error] 19178#19178: *2770 upstream timed out (110:
Connection timed out) while reading response header from upstream,
client: 2003:f9:570d:d700:15ad:6490:xxxxa, server:
mail.mail.domain.tld, request: "POST
/Microsoft-Server-ActiveSync?jQAHBBC5KA1Wkp/fDGN0EqhqG2XOBAAAAAALV2luZG93c01haWw=
HTTP/1.1", upstream:
"http://127.0.0.1:8080/Microsoft-Server-ActiveSync?jQAHBBC5KA1Wkp/fDGN0EqhqG2XOBAAAAAALV2luZG93c01haWw=",
host: "mail.domain.tld"

Further information (where applicable):

Your OS (is Apparmor or SELinux active?)
Ubuntu 18.04, Apparmor is active

Your virtualization technology (KVM/QEMU, Xen, VMware, VirtualBox etc.)
Docker

Your server/VM specifications (Memory, CPU Cores)
*-memory
description: System memory
physical id: 0
size: 15GiB
*-cpu
product: Intel(R) Core(TM) i7-2600 CPU @ 3.40GHz
vendor: Intel Corp.
physical id: 1
bus info: cpu@0
size: 2375MHz
capacity: 3800MHz

3 TB HDD Storage
Don't try to run mailcow on a Synology or QNAP NAS, do you?
No

Docker and Docker Compose versions
Client:
Version: 18.09.2
API version: 1.39
Go version: go1.10.4
Git commit: 6247962
Built: Tue Feb 26 23:52:23 2019
OS/Arch: linux/amd64
Experimental: false

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
https://github.com/mailcow/mailcow-dockerized/issues/2599, or mute
the thread
https://github.com/notifications/unsubscribe-auth/AAWV2FRTNFNKEIUFI2GEN6LPVE2CNANCNFSM4HMODIMA.

[hachre]

Please also post logs from sogo-mailcow when this happens! Thanks!

[Happyfeet01]

thanks for your quick reply @andryyy @hachre
i increase the counter to 30 and look what happens

[andryyy]

:) Yes, logs are also helpful, but I am almost sure it just run out of workers.

[Happyfeet01]

Hello again,

i changed the Timeout to 60
But Always i get the same error Message.

here is the SOGO Container log:

May 25 10:00:01 8299ee665ff7 CRON[153]: pam_unix(cron:session): session opened for user sogo by (uid=0) May 25 10:00:01 8299ee665ff7 CRON[154]: pam_unix(cron:session): session opened for user sogo by (uid=0) May 25 10:00:01 8299ee665ff7 CRON[155]: (sogo) CMD ( /usr/sbin/sogo-tool expire-sessions 60) May 25 10:00:01 8299ee665ff7 CRON[156]: (sogo) CMD ( /usr/sbin/sogo-ealarms-notify -p /etc/sogo/sieve.creds 2>/dev/null) May 25 10:00:01 8299ee665ff7 CRON[154]: pam_unix(cron:session): session closed for user sogo May 25 10:00:01 8299ee665ff7 CRON[153]: pam_unix(cron:session): session closed for user sogo May 25 10:00:04 8299ee665ff7 sogod [101]: <0x0x560fd429fed0[SOGoActiveSyncDispatcher]> Sleeping 40 seconds while detecting changes for user [email protected] in Sync... May 25 10:00:09 8299ee665ff7 sogod [101]: <0x0x560fd429fed0[SOGoActiveSyncDispatcher]> Sleeping 35 seconds while detecting changes for user [email protected] in Sync... May 25 10:00:13 8299ee665ff7 sogod [11]: [WARN] <0x0x560fd3e85250[WOWatchDogChild]> pid 101 has been hanging in the same request for 1 minutes May 25 10:00:14 8299ee665ff7 sogod [109]: mailcowdockerized_watchdog-mailcow_1.mailcowdockerized_mailcow-network "GET /SOGo.index/ HTTP/1.1" 200 2531/0 0.003 - - 0 May 25 10:00:14 8299ee665ff7 sogod [109]: <0x0x560fd45638e0[NGImap4C]> TLS started successfully. May 25 10:00:14 8299ee665ff7 sogod [101]: [ERROR] <0x0x560fd44586b0[WOHttpTransaction]> client disconnected during delivery of response for <WORequest[0x0x560fd436a460]: method=POST uri=/SOGo/Microsoft-Server-ActiveSync?jQAHBBC5KA1Wkp/fDGN0EqhqG2XOBAAAAAALV2luZG93c01haWw= app=SOGo rqKey=Microsoft-Server-ActiveSync rqPath=(null)> (len=0): the socket was shutdown May 25 10:00:14 8299ee665ff7 sogod [101]: 2003:f9:570d:d700:95c0:98:78a2:xxxx "POST /SOGo/Microsoft-Server-ActiveSync?jQAHBBC5KA1Wkp/fDGN0EqhqG2XOBAAAAAALV2luZG93c01haWw= HTTP/1.0" 200 0/316 61.241 - - 712K May 25 10:00:15 8299ee665ff7 sogod [109]: 2003:f9:570d:d700:95c0:98:78a2:xxxx "POST /SOGo/Microsoft-Server-ActiveSync?jQAHBBC5KA1Wkp/fDGN0EqhqG2XOBAAAAAALV2luZG93c01haWw= HTTP/1.0" 200 0/309 1.170 - - 0 May 25 10:00:15 8299ee665ff7 sogod [109]: 2003:f9:570d:d700:95c0:98:78a2:xxxxx "POST /SOGo/Microsoft-Server-ActiveSync?jQAHBBC5KA1Wkp/fDGN0EqhqG2XOBAAAAAALV2luZG93c01haWw= HTTP/1.0" 200 12/21 0.002 - - 0 May 25 10:00:16 8299ee665ff7 sogod [109]: <0x0x560fd4313190[NGImap4Client]> TLS started successfully. May 25 10:00:17 8299ee665ff7 sogod [109]: <0x0x560fd436ab70[SOGoActiveSyncDispatcher]> Sleeping 45 seconds while detecting changes for user [email protected] in Sync... May 25 10:00:22 8299ee665ff7 sogod [109]: <0x0x560fd436ab70[SOGoActiveSyncDispatcher]> Sleeping 40 seconds while detecting changes for user [email protected] in Sync... May 25 10:00:27 8299ee665ff7 sogod [109]: <0x0x560fd436ab70[SOGoActiveSyncDispatcher]> Sleeping 35 seconds while detecting changes for user [email protected] in Sync... May 25 10:00:32 8299ee665ff7 sogod [109]: <0x0x560fd436ab70[SOGoActiveSyncDispatcher]> Sleeping 30 seconds while detecting changes for user [email protected] in Sync... May 25 10:00:37 8299ee665ff7 sogod [109]: <0x0x560fd436ab70[SOGoActiveSyncDispatcher]> Sleeping 25 seconds while detecting changes for user [email protected] in Sync... May 25 10:00:42 8299ee665ff7 sogod [109]: <0x0x560fd436ab70[SOGoActiveSyncDispatcher]> Sleeping 20 seconds while detecting changes for user [email protected] in Sync... May 25 10:00:46 8299ee665ff7 sogod [101]: mailcowdockerized_watchdog-mailcow_1.mailcowdockerized_mailcow-network "GET /SOGo.index/ HTTP/1.1" 200 2531/0 0.004 - - 0 May 25 10:00:47 8299ee665ff7 sogod [109]: <0x0x560fd436ab70[SOGoActiveSyncDispatcher]> Sleeping 15 seconds while detecting changes for user [email protected] in Sync... May 25 10:00:52 8299ee665ff7 sogod [109]: <0x0x560fd436ab70[SOGoActiveSyncDispatcher]> Sleeping 10 seconds while detecting changes for user [email protected] in Sync...

sogo.conf

`{
SOGoCalendarDefaultRoles = (
PublicViewer,
ConfidentialDAndTViewer,
PrivateDAndTViewer
);

WOWorkersCount = "60";
SOGoACLsSendEMailNotifications = YES;
SOGoAppointmentSendEMailNotifications = YES;
SOGoDraftsFolderName = "Drafts";
SOGoJunkFolderName= "Junk";
SOGoMailDomain = "sogo.local";
SOGoEnableEMailAlarms = YES;
SOGoFoldersSendEMailNotifications = YES;
SOGoForwardEnabled = YES;
SOGoUIAdditionalJSFiles = (js/custom-sogo.js);
SOGoEnablePublicAccess = YES;

// Multi-domain setup
// Domains are isolated, you can define visibility options here.
// Example:

// SOGoDomainsVisibility = (
//  (domain1.tld, domain5.tld),
//  (domain3.tld, domain2.tld)
// );

SOGoSieveServer = "sieve://dovecot:4190/?tls=YES";
SOGoSMTPServer = "postfix:588";
WOPort = "0.0.0.0:20000";
SOGoMemcachedHost = "memcached";

SOGoLanguage = English;
SOGoMailAuxiliaryUserAccountsEnabled = YES;
SOGoMailCustomFromEnabled = YES;
SOGoMailingMechanism = smtp;
SOGoSMTPAuthenticationType = plain;

SxVMemLimit = 384;

SOGoMaximumPingInterval = 3540;

SOGoInternalSyncInterval = 45;
SOGoMaximumSyncInterval = 3540;

// 100 seems to break some Android clients
//SOGoMaximumSyncWindowSize = 99;
// This should do the trick for Outlook 2016
SOGoMaximumSyncResponseSize = 512;

WOWatchDogRequestTimeout = 20;
WOListenQueueSize = 300;
WONoDetach = YES;

SOGoIMAPAclConformsToIMAPExt = Yes;
SOGoPageTitle = "SOGo Groupware";
SOGoFirstDayOfWeek = "1";

SOGoSieveFolderEncoding = "UTF-8";
SOGoPasswordChangeEnabled = YES;
SOGoSentFolderName = "Sent";
SOGoMailShowSubscribedFoldersOnly = NO;
NGImap4ConnectionStringSeparator = "/";
SOGoSieveScriptsEnabled = YES;
SOGoTrashFolderName = "Trash";
SOGoVacationEnabled = YES;

SOGoCacheCleanupInterval = 900;
SOGoMaximumFailedLoginCount = 10;
SOGoMaximumFailedLoginInterval = 900;
SOGoFailedLoginBlockInterval = 900;

MySQL4Encoding = "utf8mb4";

//SOGoDebugRequests = YES;
//SoDebugBaseURL = YES;
//ImapDebugEnabled = YES;
//SOGoEASDebugEnabled = YES;
//LDAPDebugEnabled = YES;
//PGDebugEnabled = YES;
//MySQL4DebugEnabled = YES;
//SOGoUIxDebugEnabled = YES;
//WODontZipResponse = YES;
WOLogFile = "/dev/sogo_log";
}
`

[andryyy]

Why didnt you mention the reverse proxy?

upstream: "http://127.0.0.1:8080/Microsoft-Server-ActiveSync

You need to check your reverse proxy, as it times out and closes the connection. It shouldn't do that for ActiveSync connections.

We do need to update the docs.

Apache: You can try to add this before the first ProxyPass in your site config for the given virtual host on port 443:

ProxyPass /Microsoft-Server-ActiveSync http://127.0.0.1:8080/Microsoft-Server-ActiveSync connectiontimeout=400
ProxyPassReverse /Microsoft-Server-ActiveSync http://127.0.0.1:8080/Microsoft-Server-ActiveSync

Nginx: Before the first location / block for server 443:

  location /Microsoft-Server-ActiveSync {
    proxy_pass http://127.0.0.1:8080/;
    proxy_set_header Host $http_host;
    proxy_set_header X-Real-IP $remote_addr;
    proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
    proxy_set_header X-Forwarded-Proto $scheme;
    client_max_body_size 0;
    proxy_connect_timeout 4000;
    proxy_next_upstream timeout error;
    proxy_send_timeout 4000;
    proxy_read_timeout 4000;
  }

[andryyy]

@mkuron Can you check this? https://mailcow.github.io/mailcow-dockerized-docs/firststeps-rp/ Do you see anything wrong?

[Happyfeet01]

Ohhh. Sorry 🤷‍♂️

Thanks for your help. That makes Sense to add this Blog to the reverse Proxy

[alexander-rieder]

I have the same problem... but i am not using the reverse proxy...

Here are logs of Sogo:

sogo-mailcow_1       | Dec  3 17:10:13 b2423907706b sogod [29190]: <0x0x55b797a0b900[SOGoActiveSyncDispatcher]> Sleeping 45 seconds while detecting changes for user [email protected] in Ping...
sogo-mailcow_1       | Dec  3 17:10:13 b2423907706b sogod [29463]: 52.97.160.125 "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=user&DeviceId=c9bcc75eb01241dcaf511b463d63ad2f&DeviceType=Outlook HTTP/1.0" 200 0/91 0.532 - - 588K
sogo-mailcow_1       | Dec  3 17:10:14 b2423907706b sogod [29463]: 52.97.160.125 "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=user&DeviceId=c9bcc75eb01241dcaf511b463d63ad2f&DeviceType=Outlook HTTP/1.0" 200 0/94 0.527 - - 264K
sogo-mailcow_1       | Dec  3 17:10:14 b2423907706b sogod [29463]: 52.97.160.125 "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=user&DeviceId=c9bcc75eb01241dcaf511b463d63ad2f&DeviceType=Outlook HTTP/1.0" 200 0/116 0.527 - - 0
sogo-mailcow_1       | Dec  3 17:10:15 b2423907706b sogod [29463]: 52.97.160.125 "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=user&DeviceId=c9bcc75eb01241dcaf511b463d63ad2f&DeviceType=Outlook HTTP/1.0" 200 0/93 0.527 - - 0
sogo-mailcow_1       | Dec  3 17:10:16 b2423907706b sogod [29463]: 52.97.160.125 "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=userr&DeviceId=c9bcc75eb01241dcaf511b463d63ad2f&DeviceType=Outlook HTTP/1.0" 200 0/91 0.537 - - 264K
sogo-mailcow_1       | Dec  3 17:10:16 b2423907706b sogod [29463]: 52.97.160.125 "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=user&DeviceId=c9bcc75eb01241dcaf511b463d63ad2f&DeviceType=Outlook HTTP/1.0" 200 0/91 0.531 - - 0
sogo-mailcow_1       | Dec  3 17:10:17 b2423907706b sogod [29460]: [ERROR] <0x0x55b79798e190[WOHttpTransaction]> client disconnected during delivery of response for <WORequest[0x0x55b79957c020]: method=POST uri=/SOGo/Microsoft-Server-ActiveSync?Cmd=Ping&User=user&DeviceId=c9bcc75eb01241dcaf511b463d63ad2f&DeviceType=Outlook app=SOGo rqKey=Microsoft-Server-ActiveSync rqPath=(null)> (len=13): the socket was shutdown

[andryyy]

These are not the full logs and other than that totally fine. Your device can leave the connection. Happns all the time when switching from/to Wifi to 3g/4g/whateverg.

So these logs are ok.