View Issue Details

IDProjectCategoryView StatusLast Update
0004142SOGoActiveSyncpublic2018-09-21 16:36
Reportermodir Assigned Toludovic  
PrioritynormalSeverityminorReproducibilityhave not tried
Status closedResolutionfixed 
Platform[Server] LinuxOSRHEL/CentOSOS Version7
Product Version3.2.8 
Summary0004142: ActiveSync stops syncing
Description

We took our mailserver with SOGo live last Friday. Since then we have the problem that after one day or two the ActiveSync stops syncing.

Around the time when it stops syncing we see those error messages in the log:

Apr 10 23:55:25 sogod [60385]: <0x0x7f4b58a0e570[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null)
Apr 10 23:55:26 sogod [60385]: <0x0x7f4b54262a20[NSString]> Got invalid multibyte sequence. ToEncode: UTF-16LE FromEncode: US-ASCII.
Apr 10 23:55:27 sogod [60385]: <0x0x7f4b58a0e570[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null)
Apr 10 23:55:28 sogod [60385]: <0x0x7f4b587bbd00[SOGoActiveSyncDispatcher]> Change detected during Sync, we push the content.

I am not sure if they are related or not.

Steps To Reproduce

Is there a possibility to enable a debug mode? Since this is happening regularly I guess I could have the debug mode enabled for a while.

Additional Information

After a reboot of sogod it starts to sync again.

TagsNo tags attached.

Relationships

duplicate of 0004119 resolvedludovic Inbox will Repopulate Randomly. Users have to wait hours before Inbox is fully back in sync. 

Activities

tfu

tfu

2017-04-14 11:21

reporter   ~0011730

You can set SOGoEASDebugEnabled = YES

modir

modir

2017-04-25 11:29

reporter   ~0011756

Thanks. I have now more information in the logs. Once the sync stops I have the following messages in the log:

Apr 25 13:25:12 sogod [5805]: [ERROR] <0x0x7f5f7c3f84e0[WOHttpTransaction]> client disconnected during delivery of response for <WORequest[0x0x7f5f7c249d70]: method=POST uri=/SOGo/Microsoft-Server-ActiveSync?User=user@domain.com&DeviceId=FKHO85VQE92FLBRS464NA1MT80&DeviceType=iPhone&Cmd=Ping app=SOGo rqKey=Microsoft-Server-ActiveSync rqPath=(null)> (len=13): the socket was shutdown

It is not clear to me which socket was shutdown.

Furthermore I have many such messages in the log:

Apr 25 13:25:44 sogod [5733]: [WARN] <0x0x7f5f7c47a7d0[WOWatchDogChild]> pid 5803 has been hanging in the same request for 5 minutes
Apr 25 13:25:44 sogod [5733]: [WARN] <0x0x7f5f7c479fd0[WOWatchDogChild]> pid 5795 has been hanging in the same request for 5 minutes

Any hints what I can do no?

tfu

tfu

2017-04-29 10:01

reporter   ~0011778

The first message means that the client has disconnected before sogo was able to deliver the response. Could be a network disconnect or the client disconnected for some reason.
The seconds just means that the process is busy with polling for changes e.g. for a ping request.

Please describe more on what happens when "ActiveSync stops syncing":
Does the client stop sending requests?
Can you do a manual refresh on the client?

What does SOGoEASDebugEnabled = YES show while the problem occurs?

ludovic

ludovic

2017-05-30 19:14

administrator   ~0011853

No updates provided, suspending.

modir

modir

2017-06-07 10:22

reporter   ~0011901

I found now more useful error messages:

Jun 07 12:18:41 sogod [29584]: <0x0x7f28af6abe40[SOGoActiveSyncDispatcher]> Cache cleanup needed for device BB2BF390D7 - user: email@domain.com syncKey: 93542-232666 cache: 93488-232667
Jun 07 12:18:45 sogod [29584]: [ERROR] <0x7f28af6c0750[SOGoCacheGCSObject]:BB2BF390D7+folder91f0510082621652ed4b00001c9a4368> could not insert/update record for record '/BB2BF390D7+folder91f0510082621652ed4b00001c9a4368' in sogo_cache_folder_r_D_email_A_domain_D_com: <MySQL4Exception: 0x7f28ae732cb0> NAME:ExecutionFailed REASON:Got a packet bigger than 'max_allowed_packet' bytes

modir

modir

2017-06-07 10:42

reporter   ~0011902

Does the client stop sending requests?

Yes, in most cases there are no new requests. It seems as if the client is waiting for something.

Can you do a manual refresh on the client?

If I do a "reload" then nothing happens. If I change the settings from "push" to "sync every 15 minutes" or back then it starts to sync again after a minute or two.

What does SOGoEASDebugEnabled = YES show while the problem occurs?

Most of the time it has shown nothing at all. This time I got now for the first time the mentioned error messages.

ludovic

ludovic

2017-06-07 19:15

administrator   ~0011905

Set max_allowed_packet in your my.cnf file to a large value. Your cache exceeds the maximum allowed value by MySQL.

modir

modir

2017-06-13 09:46

reporter   ~0011923

After I had set max_allowed_packet to 64MB the error message about max_allowed_packet went away. But the original problem still exists.

Is it normal that max_allowed_packet has to be 64MB or higher? Or is there maybe another bug related to this which is not showing up in the logs yet?

modir

modir

2017-06-14 13:08

reporter   ~0011930

Yesterday I had the same problem again. I realized then that my emails didn't sync for almost one full day. At the same time the calendar and contacts did still sync. Only the emails didn't sync.

Very strange is, that during the night the device started to sync again.

Could it be that there is a cron job running on the server around 1am which cleans something up which then allows the device again to sync?

ludovic

ludovic

2017-06-16 15:36

administrator   ~0011967

There's no cronjob for sure.

modir

modir

2018-09-21 16:28

reporter   ~0013055

The problem does not exist anymore since we moved to version 4. So you can close this issue.

Issue History

Date Modified Username Field Change
2017-04-10 22:18 modir New Issue
2017-04-14 11:21 tfu Note Added: 0011730
2017-04-25 11:29 modir Note Added: 0011756
2017-04-29 10:01 tfu Note Added: 0011778
2017-05-30 19:14 ludovic Note Added: 0011853
2017-05-30 19:14 ludovic Status new => closed
2017-05-30 19:14 ludovic Assigned To => ludovic
2017-05-30 19:14 ludovic Resolution open => suspended
2017-06-07 10:22 modir Note Added: 0011901
2017-06-07 10:22 modir Status closed => feedback
2017-06-07 10:22 modir Resolution suspended => reopened
2017-06-07 10:42 modir Note Added: 0011902
2017-06-07 10:42 modir Status feedback => assigned
2017-06-07 19:15 ludovic Note Added: 0011905
2017-06-09 15:22 ludovic Relationship added duplicate of 0004119
2017-06-09 15:22 ludovic Status assigned => resolved
2017-06-09 15:22 ludovic Resolution reopened => fixed
2017-06-13 09:46 modir Note Added: 0011923
2017-06-13 09:46 modir Status resolved => feedback
2017-06-13 09:46 modir Resolution fixed => reopened
2017-06-14 13:08 modir Note Added: 0011930
2017-06-14 13:08 modir Status feedback => assigned
2017-06-16 15:36 ludovic Note Added: 0011967
2018-09-21 16:28 modir Note Added: 0013055
2018-09-21 16:36 ludovic Status assigned => closed
2018-09-21 16:36 ludovic Resolution reopened => fixed