Sogod eating up cpu and memory

roelofz

Hi,

In the last three months the performance of the server is going down.
No new users, no new devices (2 users, 6 devices in EAS and two in webmail).
The server is running in a VM (Virtualbox with 8gb, 20Gb in mainly 2 mailboxes)
I tried tuning the woworker to 20, and increased the memory to 8 Gb, disabled clamd (and I believe indexing, but cannot find that setting anymore), but still too much resources.
The cpu is modes (G1820) but functioned ok in the last 3 years I’m using Mailcow, so I am a bit puzzled.
Am I asking too much, or does this ask further investigation (and where to start searching)?

Thanks for helping!

roelofz

HI,

I’m still puzzled what is causing this.
I don’t see any alarming logging, below latest logging when the server had spykes above 50% CPU.
What can I do to make visible what is causing this?

05/10/2021, 2:34:35 PM notice [111374]: 172.22.1.1 “POST /SOGo/Microsoft-Server-ActiveSync?User=user1@mydomain.nl&DeviceId=8BN7DER7AH7JB33KJFK46BU1DG&DeviceType=iPad&Cmd=Sync HTTP/1.0” 200 336/114 140.490 - - 4070M - 12
05/10/2021, 2:34:28 PM notice [111374]: <0×0×5611223a2220[SOGoActiveSyncDispatcher]> Change detected during Sync, we push the content.
05/10/2021, 2:34:23 PM notice [111187]: <0×0×5611235d3930[SOGoActiveSyncDispatcher]> Sleeping 45 seconds while detecting changes for user user2@mydomain.nl in Ping…
05/10/2021, 2:34:20 PM notice [111187]: 192.168.0.132 “POST /SOGo/Microsoft-Server-ActiveSync?User=user2@mydomain.nl&DeviceId=URO7LITDGT1191UHKGBUGSDKV8&DeviceType=iPhone&Cmd=Sync HTTP/1.0” 200 5030/114 1.816 - - 3M - 12
05/10/2021, 2:34:20 PM notice [111187]: <0×0×5611235cceb0[SOGoActiveSyncDispatcher]> Change detected during Sync, we push the content.
05/10/2021, 2:34:20 PM notice [113493]: <0×0×561121c26980[WOHttpAdaptor]> notified the watchdog that we are ready
05/10/2021, 2:34:20 PM notice [11]: <0×0×561121b74e40[WOWatchDog]> child spawned with pid 113493
05/10/2021, 2:34:20 PM notice [11]: <0×0×561121c52c70[WOWatchDogChild]> child 82936 exited
05/10/2021, 2:34:19 PM notice [82936]: 192.168.0.225 “POST /SOGo/so/user2@mydomain.nl/Mail/0/folderINBOX/view HTTP/1.0” 200 506425/58 7.712 - - 34M - 14
05/10/2021, 2:34:19 PM notice [111187]: <0×0×561123976d90[NGImap4Client]> Note: no key found for sorting, using ‘DATE’: (null)
05/10/2021, 2:34:19 PM notice [51]: 192.168.0.225 “POST /SOGo/so/user2@mydomain.nl/Mail/0/folderINBOX/view HTTP/1.0” 200 506425/58 12.770 - - 38M - 13
05/10/2021, 2:34:18 PM notice [111187]: 192.168.0.132 “POST /SOGo/Microsoft-Server-ActiveSync?User=user2@mydomain.nl&DeviceId=URO7LITDGT1191UHKGBUGSDKV8&DeviceType=iPhone&Cmd=Ping HTTP/1.0” 200 58/0 11.924 - - 13M - 12
05/10/2021, 2:34:18 PM notice [111187]: <0×0×561121a44b10[SOGoActiveSyncDispatcher]> Change detected using Ping, we let the EAS client know to send a Sync.
05/10/2021, 2:34:17 PM notice [113418]: 192.168.0.225 “POST /SOGo/so/user2@mydomain.nl/Mail/0/folderINBOX/view HTTP/1.0” 200 814/126 73.401 - - 12M - 12
05/10/2021, 2:34:17 PM notice [111326]: mailcowdockerized_watchdog-mailcow_1.mailcowdockerized_mailcow-network “GET /SOGo.index/ HTTP/1.1” 200 2531/0 2.113 - - 17M - 12
05/10/2021, 2:34:16 PM notice [113476]: <0×0×561121dc0560[WOHttpAdaptor]> notified the watchdog that we are ready
05/10/2021, 2:34:15 PM notice [11]: [WARN] <0×0×561121cf68b0[WOWatchDogChild]> pid 111374 has been hanging in the same request for 2 minutes
05/10/2021, 2:34:15 PM notice [113418]: <0×0×561121afcfa0[SOGoCache]> Using host(s) ‘memcached’ as server(s)
05/10/2021, 2:34:15 PM notice [113418]: <0×0×561121afcfa0[SOGoCache]> Cache cleanup interval set every 900.000000 seconds
05/10/2021, 2:34:14 PM notice [11]: <0×0×561121b74e40[WOWatchDog]> child spawned with pid 113476
05/10/2021, 2:34:14 PM notice [11]: <0×0×561121c529c0[WOWatchDogChild]> (terminated due to signal 9)
05/10/2021, 2:34:14 PM notice [11]: <0×0×561121c529c0[WOWatchDogChild]> child 112887 exited
05/10/2021, 2:34:13 PM notice [81958]: 192.168.0.225 “POST /SOGo/so/user2@mydomain.nl/Mail/unseenCount HTTP/1.0” 200 21/31 6.969 - - 9M - 12
05/10/2021, 2:34:13 PM notice [112882]: 192.168.0.225 “POST /SOGo/so/user2@mydomain.nl/Mail/unseenCount HTTP/1.0” 200 21/31 75.951 - - 3M - 13
05/10/2021, 2:34:11 PM notice [108240]: <0×0×561122cebda0[SOGoActiveSyncDispatcher]> Sleeping 45 seconds while detecting changes for user user2@mydomain.nl in Ping…
05/10/2021, 2:34:11 PM notice 14:34:11.378 sogod[82936:82936] Forcing termination of EAS loop.
05/10/2021, 2:34:06 PM notice [11]: [WARN] <0×0×561121c51540[WOWatchDogChild]> pid 113418 has been hanging in the same request for 1 minutes
05/10/2021, 2:34:06 PM notice [11]: [WARN] <0×0×561121c50400[WOWatchDogChild]> pid 112882 has been hanging in the same request for 1 minutes
05/10/2021, 2:34:06 PM notice [11]: [WARN] <0×0×561121c51730[WOWatchDogChild]> pid 108240 has been hanging in the same request for 2 minutes
05/10/2021, 2:34:06 PM notice [11]: <0×0×561121c52c70[WOWatchDogChild]> sending terminate signal to pid 82936
05/10/2021, 2:34:06 PM notice [11]: [ERROR] <0×0×561121c52c70[WOWatchDogChild]> FAILURE notifying child 82936
05/10/2021, 2:34:06 PM notice [11]: <0×0×561121c52c70[WOWatchDogChild]> sending terminate signal to pid 82936
05/10/2021, 2:34:06 PM notice [11]: [ERROR] <0×0×561121c52c70[WOWatchDogChild]> exception: <NGSocketTimedOutException: 0×561121dc0810> NAME:NGSocketTimedOutException REASON:the socket was shutdown INFO:{errno = 11; error = “Resource temporarily unavailable”; stream = “{object = 0×561121c61300;}”; }
05/10/2021, 2:34:06 PM notice [11]: [ERROR] <0×0×561121c52c70[WOWatchDogChild]> socket: <NGActiveSocket[0×0×561121c61300]: mode=rw address=(null) connectedTo=<0×0×561121d91940[NGLocalSocketAddress]: /tmp/_ngsocket_11_0×561121916c70_000> receive-timeout=5.000s>
05/10/2021, 2:34:06 PM notice [11]: [ERROR] <0×0×561121c52c70[WOWatchDogChild]> FAILURE receiving status for child 82936
05/10/2021, 2:33:56 PM notice [11]: [WARN] <0×0×561121c529c0[WOWatchDogChild]> pid 112887 has been hanging in the same request for 1 minutes
05/10/2021, 2:33:39 PM notice [11]: [WARN] <0×0×561121cf68b0[WOWatchDogChild]> pid 111374 has been hanging in the same request for 1 minutes
05/10/2021, 2:32:51 PM notice [11]: [WARN] <0×0×561121c51730[WOWatchDogChild]> pid 108240 has been hanging in the same request for 1 minutes
05/10/2021, 2:32:47 PM notice [108240]: <0×0×561122cebda0[SOGoActiveSyncDispatcher]> Sleeping 45 seconds while detecting changes for user user2@mydomain.nl in Ping…
05/10/2021, 2:32:32 PM notice [112882]: mailcowdockerized_watchdog-mailcow_1.mailcowdockerized_mailcow-network “GET /SOGo.index/ HTTP/1.1” 200 2531/0 0.317 - - -13344K - 13
05/10/2021, 2:32:24 PM notice [112887]: <0×0×5611235de880[SOGoActiveSyncDispatcher]> Sleeping 45 seconds while detecting changes for user user1@mydomain.nl in Ping…
05/10/2021, 2:32:23 PM notice [112887]: [WARN] <0×0×5611218ba850[SOGoWebDAVAclManager]> entry ‘{DAV:}write-content’ already exists in DAV permissions table
05/10/2021, 2:32:23 PM notice [112887]: [WARN] <0×0×5611218ba850[SOGoWebDAVAclManager]> entry ‘{DAV:}write-properties’ already exists in DAV permissions table
05/10/2021, 2:32:23 PM notice [112887]: [WARN] <0×0×5611218ba850[SOGoWebDAVAclManager]> entry ‘{DAV:}write’ already exists in DAV permissions table
05/10/2021, 2:32:23 PM notice [111374]: <0×0×561121c9aff0[NGImap4Client]> Note: no key found for sorting, using ‘DATE’: (null)
05/10/2021, 2:32:14 PM notice [111374]: 89.205.135.241 “POST /SOGo/Microsoft-Server-ActiveSync?User=user1@mydomain.nl&DeviceId=B69JGO3VRL06J012UNIG4PN4QK&DeviceType=iPhone&Cmd=Ping HTTP/1.0” 200 13/191 912.755 - - 1M - 12
05/10/2021, 2:32:12 PM notice [112887]: 192.168.0.238 “POST /SOGo/Microsoft-Server-ActiveSync?User=user1@mydomain.nl&DeviceId=8BN7DER7AH7JB33KJFK46BU1DG&DeviceType=iPad&Cmd=Sync HTTP/1.0” 200 336/114 77.638 - - 4048M - 12
05/10/2021, 2:32:05 PM notice [112887]: <0×0×561121d45c90[SOGoActiveSyncDispatcher]> Change detected during Sync, we push the content.
05/10/2021, 2:32:01 PM notice [11]: [WARN] <0×0×561121cf68b0[WOWatchDogChild]> pid 111374 has been hanging in the same request for 15 minutes
05/10/2021, 2:31:58 PM notice [112882]: 192.168.0.225 “POST /SOGo/so/user2@mydomain.nl/Mail/0/folderINBOX/view HTTP/1.0” 200 506425/58 3.276 - - 18M -

roelofz

Same time period CPU monitoring:

When running top sogod is causing the high cpu, so it is not another process on the system.

roelofz

Hi,

Nobody able to give me some diagnosing tips or what to tune?

roelofz

I am flabbergasted with all the responses.
I don’t know what to do anymore, other than looking for other mailsoftware.

Dissapointing….

diekuh

You may try to reset the EAS devices. Or disable EAS devices and see which causes the trouble. Seems to be user2? Reset their EAS device (login as this user from mailcow UI and click the button to reset EAS).

You may want to disable the account on that device before.

roelofz

Hi Diekuh,
This is the solution, at least for the last 7 hours normal low cpu behavior.
Finally I can lower the system specs back to the way the were, six month ago.
Big thanks for your tip!
Is there a way to clear these caches using a script, or is it better to only clear them once the the sogo deamon is filling up again?

diekuh

This should never happen. I don’t know why it happened. Was it a problem with an iPhone? Or mac OS?

roelofz

2 Iphones and 2 Ipads (1 on iOS 12, still receiving security updates).
I don’t know which one was the cause, I cleared the caches for both users at once.
Server has been running flawlessly in the last 3 days, with one spike during 20 minutes yesterday evening (no source found from that spike yet). I will follow this if it returns and in what schedule it wil return.
WOworker resets Sogo a lot (all the time), so changed SxVMemLimit = 512, was 256, lowered worker count from 20 to 10.
But this is more back tuning, because of all the tests I did while researching this problem.
I will follow the logs if this will make a change.

Again thanks for your help, very happy to know now the EAS cache can be a source of trouble!

diekuh

If it happens again, you may want to enable EAS debugging in sogo.conf and restart the container. It will post the whole EAS message it syncs to the logs, it’s kind of messy. But after all I think you’d be able to identify the message/s causing the loop (they will probably flood the logs). 🙂

roelofz

Thanks for the tip. I have SAR monitoring the cpu performance now, so I will be warned next time.
Ik have an alerting script, what is able to send out emails, but I can’t get it working to email to the local host (next project for me).
Debugging tip is noted in the remark of sogo.conf to remind me.

Thanks again, happy to have it working again!