Uncaught TypeError: mapi_message_setreadflag(): Argument #1 ($msg) must be of type resource, bool given

[amaccuish]

04/02/2023 02:38:31 [ 4695] [ WARN] [xxx@xxx.xxx.xxx] Unable to Fetch 'Uaed3e:51000000a5187b6fbcdcea1ed03c565700000003be8a'
04/02/2023 02:38:39 [ 4688] [ WARN] [xxx@xxx.xxx.xxx] Unable to Fetch 'Uaed3e:51000000a5187b6fbcdcea1ed03c565700000003be84'
04/02/2023 02:38:40 [ 4630] [FATAL] [xxx@xxx.xxx.xxx] Fatal error: /usr/share/grommunio-sync/lib/grommunio/importer.php:511 - Uncaught TypeError: mapi_message_setreadflag(): Argument #1 ($msg) must be of type resource, bool given in /usr/share/grommunio-sync/lib/grommunio/importer.php:511
Stack trace:
#0 /usr/share/grommunio-sync/lib/grommunio/importer.php(511): mapi_message_setreadflag(false, 0)
#1 /usr/share/grommunio-sync/lib/request/sync.php(1510): ImportChangesICS->ImportMessageReadFlag('Uaed3e:51000000...', '1')
#2 /usr/share/grommunio-sync/lib/request/sync.php(536): Sync->importMessage(Object(SyncParameters), Array, 'Modify', Object(SyncMail), false, 'Uaed3e:51000000...', false, 1)
#3 /usr/share/grommunio-sync/lib/request/requestprocessor.php(98): Sync->Handle(0)
#4 /usr/share/grommunio-sync/index.php(114): RequestProcessor::HandleRequest()
#5 {main}
thrown (1)
04/02/2023 02:38:43 [ 4556] [ WARN] [xxx@xxx.xxx.xxx] Unable to Fetch 'Uaed3e:51000000a5187b6fbcdcea1ed03c565700000003be7f'
04/02/2023 02:38:45 [ 4630] [ERROR] [xxx@xxx.xxx.xxx] LoopDetection->ProcessLoopDetectionPreviousConnectionFailed(): Command 'Sync' at 04/02/2023 02:38:39 with pid '4630' terminated unexpectedly or is still running.
04/02/2023 02:38:45 [ 4630] [ERROR] [xxx@xxx.xxx.xxx] Please check your logs for this PID and errors like PHP-Fatals or Apache segmentation faults and report your results to the grommunio dev team.
04/02/2023 02:38:45 [ 4630] [ WARN] [xxx@xxx.xxx.xxx] Unable to Fetch 'Uaed3e:51000000a5187b6fbcdcea1ed03c565700000003be7d'
04/02/2023 02:38:45 [ 4619] [ WARN] [xxx@xxx.xxx.xxx] Unable to Fetch 'Uaed3e:51000000a5187b6fbcdcea1ed03c565700000003be7c'
04/02/2023 02:40:04 [ 4608] [ WARN] [xxx@xxx.xxx.xxx] Unable to Fetch 'Uaed3e:51000000a5187b6fbcdcea1ed03c565700000003b657'
04/02/2023 02:40:35 [ 4688] [ WARN] [xxx@xxx.xxx.xxx] LoopDetection->updateProcessStack(): CAS failed on try 1!
04/02/2023 02:41:07 [ 4734] [ WARN] [xxx@xxx.xxx.xxx] LoopDetection->updateProcessStack(): CAS failed on try 1!
04/02/2023 02:45:05 [ 4695] [ WARN] [xxx@xxx.xxx.xxx] Unable to Fetch 'Uaed3e:51000000a5187b6fbcdcea1ed03c565700000003be8a'
04/02/2023 02:45:06 [ 4762] [ WARN] [xxx@xxx.xxx.xxx] Unable to Fetch 'Uaed3e:51000000a5187b6fbcdcea1ed03c565700000003be84'
04/02/2023 02:45:06 [ 4734] [ WARN] [xxx@xxx.xxx.xxx] Unable to Fetch 'Uaed3e:51000000a5187b6fbcdcea1ed03c565700000003be7f'
04/02/2023 02:45:07 [ 4688] [ WARN] [xxx@xxx.xxx.xxx] Unable to Fetch 'Uaed3e:51000000a5187b6fbcdcea1ed03c565700000003be7d'
04/02/2023 02:45:08 [ 4736] [ WARN] [xxx@xxx.xxx.xxx] Unable to Fetch 'Uaed3e:51000000a5187b6fbcdcea1ed03c565700000003be7c'

[amaccuish]

Happy to mail a wetransfer link of the wbxml log.
These error seems to be causing an iPhone and iPad to resync. Only affects one mailbox.

Around the same time, there are lots of these errors in the logs

StatusException: ExportChangesICS->InitializeExporter(): Error, mapi_exportchanges_config() failed: 0x80004005 - code: 12 - file: /usr/share/grommunio-sync/lib/grommunio/exporter.php:216

Using the grommunio appliance with the community repos.
grommunio-admin-api-1.9.28.774374b-lp154.46.1.noarch
grommunio-admin-common-6.cb985db-lp154.2.1.noarch
grommunio-admin-web-2.6.0.43.2feaeef-lp154.35.1.noarch
grommunio-antispam-3.4-lp154.2.1.x86_64
grommunio-common-10.e94d08a-lp154.7.1.x86_64
grommunio-cui-1.0.241.dbe4906-lp154.45.1.noarch
grommunio-dav-1.1.37.d5b6463-lp154.10.1.noarch
grommunio-dbconf-1.1.1.da20a46-lp154.4.2.x86_64
grommunio-error-pages-1.0.6.9c50afb-lp154.3.1.noarch
grommunio-imapsync-2.178-lp154.1.1.noarch
grommunio-index-0.1.25.3e826c9-lp154.31.1.x86_64
grommunio-release-2022.12.1-lp154.3.1.x86_64
grommunio-setup-1.0.68.bb1014d-lp154.7.1.noarch
grommunio-sync-1.1.62-lp154.75.1.noarch
grommunio-web-3.1.197.c7957cc-lp154.157.1.noarch
gromox-2.3.0.de34c2d-lp154.1.1.x86_64
gromox-debuginfo-2.3.0.de34c2d-lp154.1.1.x86_64
gromox-debugsource-2.3.0.de34c2d-lp154.1.1.x86_64

[amaccuish]

Could it be that grommunio sync can't handle graceful restarts of gromox-zcore?

[amaccuish]

Hmm something seems to go wrong with exmdb around the time the mobile devices of the affected user go blank:

[2023-02-04 21:56:57.078597]: exmdb_client: gx_inet_connect to [::1]:5000: Connection refused

And gromox-http seems to restart:

Feb 04 21:47:53 mx01 http[11781]: system: HTTP daemon is now running
Feb 04 21:56:57 mx01 systemd[1]: Stopping Gromox HTTP service...
Feb 04 21:56:57 mx01 systemd[1]: gromox-http.service: Deactivated successfully.
Feb 04 21:56:57 mx01 systemd[1]: Stopped Gromox HTTP service.
Feb 04 21:56:57 mx01 systemd[1]: Started Gromox HTTP service.

zcore also seems to restart a few times.

I've turned up logging for zcore, for exmdb, is there a way I can turn the logging up there? Would that be by turning up the logging of gromox-http with http_log_level? I guess this would be better placed in the community forums rather than grommunio-sync as it looks like a wider issue than just sync?

[amaccuish]

After the latest updates, this error has stopped appearing, however, I notice in the WBXML the following when these resyncs occur:

14/02/2023 19:53:49 [ 3375] [DEBUG] DeviceManager->GetBackendIdForFolderId(): no backend-folderid available for 'kDAMailAccountAllMailboxesFolderID', returning as is.
14/02/2023 19:53:49 [ 3375] [INFO] NoHierarchyCacheAvailableException: Folderid 'kDAMailAccountAllMailboxesFolderID' is not fully synchronized on the device - code: 0 - file: /usr/share/grommunio-sync/lib/core/devicemanag>
14/02/2023 19:53:49 [ 3375] [INFO] Full device resync requested
14/02/2023 19:53:49 [ 3375] [DEBUG] StateManager::UnLinkState('Udeb91'): saved state '4a8f0d88-d3b8-4590-8544-513729291c36' will be deleted.
14/02/2023 19:53:49 [ 3375] [DEBUG] Grommunio->CleanStates(): Found 1 states to clean (4a8f0d88-d3b8-4590-8544-513729291c36)
14/02/2023 19:53:49 [ 3375] [DEBUG] Grommunio->CleanStates(): Found 1 states to clean (4a8f0d88-d3b8-4590-8544-513729291c36-fd)
14/02/2023 19:53:49 [ 3375] [DEBUG] Grommunio->CleanStates(): Found 0 states to clean (4a8f0d88-d3b8-4590-8544-513729291c36-fs)
14/02/2023 19:53:49 [ 3375] [DEBUG] Grommunio->CleanStates(): Found 0 states to clean (4a8f0d88-d3b8-4590-8544-513729291c36-bs)
14/02/2023 19:53:49 [ 3375] [DEBUG] StateManager::UnLinkState('U47b04'): saved state '1783f4ac-af2e-4006-94b7-4d383cd58058' will be deleted.
14/02/2023 19:53:49 [ 3375] [DEBUG] Grommunio->CleanStates(): Found 2 states to clean (1783f4ac-af2e-4006-94b7-4d383cd58058)
14/02/2023 19:53:49 [ 3375] [DEBUG] Grommunio->CleanStates(): Found 1 states to clean (1783f4ac-af2e-4006-94b7-4d383cd58058-fd)
14/02/2023 19:53:50 [ 3375] [DEBUG] Grommunio->CleanStates(): Found 1 states to clean (1783f4ac-af2e-4006-94b7-4d383cd58058-fs)
14/02/2023 19:53:50 [ 3375] [DEBUG] Grommunio->CleanStates(): Found 0 states to clean (1783f4ac-af2e-4006-94b7-4d383cd58058-bs)
14/02/2023 19:53:50 [ 3375] [WARN] /usr/share/grommunio-sync/lib/core/asdevice.php:255 Undefined property: stdClass::$folderid (2)
14/02/2023 19:53:50 [ 3375] [WARN] /usr/share/grommunio-sync/lib/core/asdevice.php:255 Undefined property: stdClass::$folderid (2)
14/02/2023 19:53:50 [ 3375] [WARN] /usr/share/grommunio-sync/lib/core/asdevice.php:255 Undefined property: stdClass::$folderid (2)
14/02/2023 19:53:50 [ 3375] [WARN] /usr/share/grommunio-sync/lib/core/asdevice.php:255 Undefined property: stdClass::$folderid (2)
14/02/2023 19:53:50 [ 3375] [WARN] /usr/share/grommunio-sync/lib/core/asdevice.php:255 Undefined property: stdClass::$folderid (2)
14/02/2023 19:53:50 [ 3375] [WARN] /usr/share/grommunio-sync/lib/core/asdevice.php:255 Undefined property: stdClass::$folderid (2)
14/02/2023 19:53:50 [ 3375] [WARN] /usr/share/grommunio-sync/lib/core/asdevice.php:255 Undefined property: stdClass::$folderid (2)

14/02/2023 19:53:49 [ 3375] [WBXML] I
14/02/2023 19:53:49 [ 3375] [WBXML] I
14/02/2023 19:53:49 [ 3375] [WBXML] I
14/02/2023 19:53:49 [ 3375] [WBXML] I
14/02/2023 19:53:49 [ 3375] [WBXML] I 0
14/02/2023 19:53:49 [ 3375] [WBXML] I
14/02/2023 19:53:49 [ 3375] [WBXML] I
14/02/2023 19:53:49 [ 3375] [WBXML] I kDAMailAccountAllMailboxesFolderID
14/02/2023 19:53:49 [ 3375] [WBXML] I
14/02/2023 19:53:49 [ 3375] [DEBUG] SyncParameters->RemoveSyncKey(): saved sync key removed
14/02/2023 19:53:49 [ 3375] [DEBUG] DeviceManager->GetBackendIdForFolderId(): no backend-folderid available for 'kDAMailAccountAllMailboxesFolderID', returning as is.
14/02/2023 19:53:49 [ 3375] [INFO] NoHierarchyCacheAvailableException: Folderid 'kDAMailAccountAllMailboxesFolderID' is not fully synchronized on the device - code: 0 - file: /usr/share/grommunio-sync/lib/core/devicemanag>
14/02/2023 19:53:49 [ 3375] [INFO] Full device resync requested

Can this be related?

[gromandreas]

Hi @amaccuish ,

there will be some fixes related to the states coming soon. We are currently testing them to make sure they don't break sync, but I guess we will commit them this week.

Could it be that grommunio sync can't handle graceful restarts of gromox-zcore?

It depends on how you define can't handle. If the restart happens in the middle of the sync process, it might happen that it will cause a full resync of the device.

It the restart happens when the device is in Ping and basically idling, it will probably just issue another Ping request and continue waiting for changes and idling as if nothing happened. Of course some devices might not like the disconnection in Ping also and do a full resync.

I've turned up logging for zcore, for exmdb, is there a way I can turn the logging up there? Would that be by turning up the logging of gromox-http with http_log_level? I guess this would be better placed in the community forums rather than grommunio-sync as it looks like a wider issue than just sync?

Yes, you can turn the log level of gromox-http with http_log_level. The most verbose value is 6.

For issues that may span several components I think that the community forum is indeed a better place to post. But we also check the issues on github and will pick them up eventually.

[amaccuish]

hi @gromandreas,

thank you for your reply, looking forward to testing those fixes :)

StateNotFoundException: Grommunio->getStateMessage(): Could not locate the state message 'devicedata' (counter: false

Got this again this morning, redis is running, so I guess this is the case of all the resyncs.

I turned up logging elsewhere but nothing jumps out, just a lot of ZRPC fails.

I'll keep an eye out for the commits and will let you know.

[amaccuish]

As an idea, can I suggest, for large inboxes, the SYNC_FILTERTIME_MAX could be set to allow older flagged emails to be syncronised (i.e. only sync up to 30 days of email, but sync all flagged email).

Then users can set to sync only 30 days, but have access to older important emails. With only 30 days, the chances of state going missing or the impact of a full resync would be reduced.

[amaccuish]

So since the last update, we haven't had a resync, just lots of

Grommunio->checkAdvisedSinkStores(): could not access advised store store 'Resource id #9' - failed with code 0x000004B9

I'll leave this open for one more week then will consider closed. Hopefully this is fixed =D

[grammmike]

closing, as fixed with zcore adaptions and improved session handling in sync