Errors syncing large mailbox

fkoyer

I am setting up a new customer who has a 22 GB mailbox. I’m using z-push with an IMAP backend. Outlook starts syncing fine at first but eventually hangs and I see the following errors in the logs (some errors are repeated over and over again but I only included them once for brevity)

22/12/2021 18:24:55 [ 9872] [ INFO] [xxxxx@xxxxxxxxxx] StateNotFoundException: SqlStateMachine->GetStateHash(): Could not locate state with error code: 00000 - code: 0 - file: /var/www/vhosts/activesync/backend/sqlstatemachine/sqlstatemachine.php:145
22/12/2021 18:24:55 [ 9872] [ INFO] [xxxxx@xxxxxxxxxx] StateNotFoundException: SqlStateMachine->GetState(): Could not locate state - code: 0 - file: /var/www/vhosts/activesync/backend/sqlstatemachine/sqlstatemachine.php:197
22/12/2021 18:25:40 [ 9872] [ERROR] [xxxxx@xxxxxxxxxx] BackendIMAP->update_calendar_attendee(): event not found or duplicated event
22/12/2021 18:25:45 [10462] [WARN] [xxxxx@xxxxxxxxxx] /var/www/vhosts/activesync/include/mimeDecode.php:865 iconv(): Detected an illegal character in input string (8)
22/12/2021 18:32:04 [15700] [WARN] [xxxxx@xxxxxxxxxx] SyncObject->Check(): object from type SyncMail: parameter 'to' contains an invalid email address 'undisclosed-recipients:;'. Address is removed.
22/12/2021 18:32:11 [15700] [ERROR] [xxxxx@xxxxxxxxxx] TimezoneUtil::guessTZNameFromPHPName() no compatible timezone found for 'Haiti Standard Time'. Returning 'GMT Standard Time'. Please contact the Z-Push dev team.
22/12/2021 18:32:53 [15700] [WARN] [xxxxx@xxxxxxxxxx] /var/www/vhosts/activesync/include/mimeDecode.php:731 Undefined offset: 3 (8)
22/12/2021 18:34:36 [18851] [ERROR] [xxxxx@xxxxxxxxxx] BackendIMAP->delete_calendar_dav(): event not found, we will end with zombie events
22/12/2021 18:36:42 [18361] [ERROR] [xxxxx@xxxxxxxxxx] z_RFC822 error: Validation failed for: Epicurean Atlanta
22/12/2021 18:37:09 [18361] [FATAL] [xxxxx@xxxxxxxxxx] Fatal error: /var/www/vhosts/activesync/include/mimeDecode.php:493 - Allowed memory size of 268435456 bytes exhausted (tried to allocate 41069168 bytes) (1)
22/12/2021 18:56:12 [ 5239] [WARN] [xxxxx@xxxxxxxxxx] /var/www/vhosts/activesync/backend/caldav/caldav.php:1620 Undefined offset: 2 (8)
22/12/2021 18:57:59 [21531] [ERROR] [xxxxx@xxxxxxxxxx] LoopDetection->ProcessLoopDetectionPreviousConnectionFailed(): Command 'Sync' at 22/12/2021 18:36:38 with pid '18361' terminated unexpectedly or is still running.
22/12/2021 18:57:59 [21531] [ERROR] [xxxxx@xxxxxxxxxx] Please check your logs for this PID and errors like PHP-Fatals or Apache segmentation faults and report your results to the Z-Push dev team.
22/12/2021 20:23:42 [ 7329] [WARN] [xxxxx@xxxxxxxxxx] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict
22/12/2021 20:24:18 [ 6894] [WARN] [xxxxx@xxxxxxxxxx] Not possible to determine class of request. Request did not contain class and apparently there is an issue with the HierarchyCache.
22/12/2021 20:25:13 [10181] [ INFO] [xxxxx@xxxxxxxxxx] NoHierarchyCacheAvailableException: Folderid 'i/79981518' is not fully synchronized on the device - code: 0 - file: /var/www/vhosts
activesync/lib/core/devicemanager.php:466
22/12/2021 20:25:13 [10181] [ INFO] [xxxxx@xxxxxxxxxx] Full device resync requested
22/12/2021 20:25:13 [10181] [WARN] [xxxxx@xxxxxxxxxx] Not possible to determine class of request. Request did not contain class and apparently there is an issue with the HierarchyCache.
22/12/2021 20:25:19 [10181] [ INFO] [xxxxx@xxxxxxxxxx] HandlePing(): unknown collection 'i/ae685763', triggering HierarchySync
22/12/2021 20:25:19 [10181] [ INFO] [xxxxx@xxxxxxxxxx] NoHierarchyCacheAvailableException: Folderid 'd/contacts' is not fully synchronized on the device - code: 0 - file: /var/www/vhosts
activesync/lib/core/devicemanager.php:466
22/12/2021 20:29:22 [10181] [ INFO] [xxxxx@xxxxxxxxxx] StateNotFoundException: No hierarchy UUID linked to device. Requesting folder resync. - code: 0 - file: /var/www/vhosts/activesync/l
ib/core/statemanager.php:486

I’m not sure which errors are relevant. I increased the PHP memory limit to 1024MB so maybe that will help.

Output from z-push-admin:

DeviceId:               0d82ae60805c4423b11a2e771665ac13
Device type:            WindowsOutlook
UserAgent:              Outlook/16.0 (16.0.14701.20230; x86)
ActiveSync version:     14.0
First sync:             2021-12-22 18:51
Last sync:              2021-12-22 20:23
Sync Period:            unlimited (0)
Total folders:          16
Short folder Ids:       No
Synchronized folders:   15 (10 in progress)
Synchronized data:      Emails(12) Calendars Tasks Contacts
Synchronization progress:
        Folder: Junk                 Sync: Initialized   Status:  0% (0/38)
        Folder: Sent                 Sync: Synchronizing Status:  7% (436/5979)
        Folder: Executive Committee  Sync: Initialized   Status:  0% (0/3)
        Folder: Fiely                Sync: Initialized   Status:  0% (0/4)
        Folder: Janet                Sync: Initialized   Status:  0% (0/4)
        Folder: completed            Sync: Initialized   Status:  0% (0/6)
        Folder: Madison              Sync: Initialized   Status:  0% (0/104)
        Folder: Starred              Sync: Initialized   Status:  0% (0/9)
        Folder: Important            Sync: Initialized   Status:  0% (0/9253)
        Folder: Inbox                Sync: Synchronizing Status: 23% (6331/27133)
Additional Folders:     none
Status:                 Not available
WipeRequest on:         not set
WipeRequest by:         not set
Wiped on:               not set
Policy name:            default
Attention needed:       No errors known

Any advice is appreciated.

Thanks
Kent

fkoyer

I forgot to mention that the Synchronization progress does not seem to be changing. It’s still at the same percentage that it was 15 hours ago.

Gerald

@fkoyer said in Errors syncing large mailbox:

22/12/2021 18:37:09 [18361] [FATAL] [xxxxx@xxxxxxxxxx] Fatal error: /var/www/vhosts/activesync/include/mimeDecode.php:493 - Allowed memory size of 268435456 bytes exhausted (tried to allocate 41069168 bytes)

I’m not sure which errors are relevant. I increased the PHP memory limit to 1024MB so maybe that will help.

that seems highly relevant. Did it help? It seems limit was 256MB before and it was unable to allocate 41MB to decode a message.

fkoyer

Hi @gerald ,

It did not help so I built a new server and reinstalled from scratch. It’s working better now thanks.

JungleMarc

I had to raise my php memory limit as well in the past. I run large inboxes, +20gb.

256meg memory limit never been enough for me. That being said I should keep an eye on the php memory usage.

fkoyer

@junglemarc What do you have your limit set to? Is there a good rule of thumb for how much memory you need based on number of mailboxes or mailbox size?

liverpoolfcfan

@fkoyer said in Errors syncing large mailbox:

435

The main issue with Outlook tends to be related to the sheer quantity of data is requests at a time. It defaults to requesting 512 items, and if these are emails, particularly with lots of attachments, it can be an extremely slow process to gather all that data from the backend.

Outlook will often think it’s previous request has failed, even though the backend is still working on it, and will issue the same request again. This causes the z-push server to have 2 competing requests running against the same mailbox and things can quickly get broken.

If you are seeing repeated errors or hung syncs, I would suggest lowering the

   define('SYNC_MAX_ITEMS', 512);

to 256 or even 128 to see if you get better performance.

fkoyer

@liverpoolfcfan Thanks I’ll try that.

JungleMarc

@fkoyer Raised it once to 768M, I should check but the 256M is the recommended value.

There was log mention of the php running out of memory a while ago… I wish I would of saved and pasted it on here.

That being said, I will try to remind myself to check the max memory size php uses.