z-push 2.4.5 sync issue - 0xFFFFFFFF8004010F

fbartels

@thctlo the z-push packaging is part of the git repo, but for core nothing like this exists (its anyways a bit OBS specific, as this is what we use for building) a not totally up to date snapshot can be found at https://build.opensuse.org/package/show/server:mail:kopano/kopano.

weini

I can confirm now, that migrating from MariaDB 10.3 to MySQL 8.0 resolves the issue.
I´m on Debian 10, but using current (2 week old nightlys) packages from kopano.io and the current z-push 2.5.1.

I did a migration on database level (mostly using InnoDB transportable tablespaces, partially simple mysqldump). So this means that having an “old” Kopano install with dozends of entries in the version table by itself does not trigger the issue.

Consequences from my perspective:

forget about the Debian repository packages for now, they´re not properly tested - crap IMHO
you have to use MySQL if you´ve more than 3.000 objects in your larger folders

It is a shame that we´re suffering from such problems. But don´t get me wrong, this is no blaming. This is free software and it needs our effort to improve it.

@fbartels: I can´t provide you with a full dump of all my personal emails to reproduce the problem. But I now have two db schemas available, one working and one triggering the issue. Pls let me know how I may further supprt you debugging the issue.

compsos

@thctlo When running z-push-top does it display the php-mapi version? We have a D10 system that works but from the repo it could not load php-mapi. Eventually added other z-push components from D9 code.

bcoms

I can hereby confirm that migrating to mysql 8 solves the issue. With MariaDB I was able to solve the issue partially for calendar items by running kopano-fschk, however the tool only complained about entries which were created by Outlook when acting on appointment e-mails from other users. However kopano-fschk never solved the problem for e-mails as no problems were reported anyways.

bcoms

@weini
I can second your opinion about the Debian Kopano packages. No idea how they made it into the stable distribution in that poor condition - they should be removed asap.

MySQL: I already had problems with MariaDB and inboxes with only about 1K items.

thctlo

@bcoms because now, they can use buster-backports.
If kopano was not in buster, no backport could be made and push into buster.

General_Probe

I’m also on Buster with Debian Kopano 8.7.0-3 and switched from MariaDB 10.3 to MySQL 5.7. It works fine since last wednesday now. I will file a bug report soon at debians bug reporting tool.

I also dont know how these packages got into Debian Stable. I think I hold 90% of the bugs for kopano at debian …
Kopano-Search has lots of apparmor issues
Kopano-Server is missing config files (ldap.cfg and admin.cfg) also user creation, deletion, updating is not working with current config on ldap

I also dont want to blame the Debian developers. They are very helpful, but it is just annoying to run from one issue into another.

fbartels

@weini said in z-push 2.4.5 sync issue - 0xFFFFFFFF8004010F:

But I now have two db schemas available, one working and one triggering the issue. Pls let me know how I may further supprt you debugging the issue.

Sure, its worth a try.

rolek

@fbartels I have a debug log of this problem (with the ICS and SQL backend logs enabled). Something struck me as odd while comparing the logs with the code.

I do see a log line with “MatchRestrictions: matching 1000 rows”, but I don’t see the line with “MatchRestrictions: %zu match(es) out of %d rows (%d properties)” that is logged a little later in that function. So somewhere in between we hit an error condition.

I’m currently rebuilding kopanocore with some extra debugging and might have some additional information soon.

rolek

@fbartels The function that fails is the call to gcache->GetObject() in ECGetContentChangesHelper::MatchRestrictions()

This is with 8.7.0, btw.

rolek

@fbartels Some more info: I see calls to MatchRestrictions() that succeed. In these cases I get the “matching 43 rows” log, then the loop that iters over index_objs runs with the same number of iterations as the number of rows, then finally I get a log saying "18 match(es) out of 43 rows (1 properties).

Every time Z-push logs the sync issue, the log shows “matching 1000 rows”, the loop that iters over index_objs doesn’t run any iterations at all, and when gcache->GetObject() is called, ulObjId is 0.

This is about as far as I’ll get, since I’m not a C++ programmer. I hope this is useful to you.
I’d be happy to test any patches; I can rebuild kopanocore myself.

Best regards, Roel

rolek

@fbartels I tried to get a bit further. Running with the cache debug log provided some additional info. Whenever the amount of rows is less than 1000, they can be retrieved from the cache:

MatchRestrictions: matching 940 rows
cache: Get object ids from props total ids 940 from disk 940
...
MatchRestrictions: 28 match(es) out of 940 rows (1 properties)

Whenever the number of rows is 1000, they cannot:

MatchRestrictions: matching 1000 rows
cache: Get objects ids warning 1000 objects not found
cache: Get object ids from props total ids 1000 from disk 1000
cache: Get object id 0 error 0x80000002

jengelh

@rolek said in z-push 2.4.5 sync issue - 0xFFFFFFFF8004010F:

@fbartels The function that fails is the call to gcache->GetObject() in ECGetContentChangesHelper::MatchRestrictions()

This is with 8.7.0, btw.

8.7.5 is current. The cache fixes (so far) were done months ago in 8.7.1.

rolek

Rebuilding kopano-libs with 500 instead of 1000 items in provider/libserver/ECICS.cpp, function getchanges_contents() does seem to solve the problem. That got me thinking: maybe we are hitting the max_allowed_packet size? The default for MariaDB is 16MB, the default for MySQL 8 is 64MB.

vincentvana

I can confirm that the problem still exists (with mail, calendar AND contacts) with z-push (2.4.5 and 2.5.1) and kopano-core 8.7.83.106.59c4d1516. If I interpret the thread correctly, the general theory is that it’s a database issue.

My personal setup:

Debian 10
Apache 2.4
php7.3-fpm
MariaDB 10.3
Official z-push 2.5.1
Official kopanocore 8.7.83.106.59c4d1516

I have not found a solution using the current software. Existing syncs work fine, new ones look like they’re choking but don’t know why. Topic 1678 is about the same issue and suggests disabling the enhanced ics, but this does not fix the issue for me. This probably works if the issue is only on the calendar. (Tried it anyway)

Replacing the database software is a BIG step that I’m not willing to take … yet. I did test a full mysqldump and restore of the database. Maybe migrating from mariadb to mysql solved the problem because of the dump/restore…but nope, that’s not it.

I’ve tested the max_allowed_packet setting suggested by rolek and increased it to the mysql8 default of 64M but this also does not solve the issue:

10/10/2019 12:06:01 [28264] [WARN] [user] StatusException: ExportChangesICS->InitializeExporter(): Error, mapi_exportchanges_config() failed: 0xFFFFFFFF8004010F - code: 12 - file: /usr/share/z-push/backend/kopano/exporter.php:230

Maybe there’s more size settings that we need to tweak.

rolek

I can report that the patch from https://bugs.debian.org/cgi-bin/bugreport.cgi?att=1;bug=939751;filename=fix-zpush-sync-error.patch;msg=15 fixes the problem for us. It would be nice if somebody else could confirm this.

Regards, Roel

jengelh

If you think you hit max_allowed_packet_size, you want to test that theory:

there should be log messages by k-server (possibly with log_level=0x20006 see manpage for the value)
lower max_allowed_packet_size and observe even more queries being rejected
conversely, raise max_allowed_packet and observe z-push succeeding(?)

Moreover, if you raise the ICS value (in that patch) from 1000 to 500, you should be observing a change in SQL query lengths - and compare with max_allowed_packet_size too.

vincentvana

Finally found a solution. After looking for hours at the increased log level suggested by jengelh and messing with a lot of settings without much luck (even having to restore the whole DB at some point). It looks like my error was related to a corruption in a mailbox. By lowering the SYNC_MAX_ITEMS, in the z-push config, all the way down to 5, z-push started syncing that account on the three new devices (already connected devices were working fine). Maybe running into a corruption stops syncing of the whole batch, and if that batch contains part of the hierarchy, it never manages to set it up.

If that is the case, it can be “fixed” by adding this situation to the loopdetection. It would make z-push more robust when dealing with these errors in a backend.

Anyway, to permanently fix this problem for me:

kopano-backup user
kopano-storeadm -D -n user
kopano-storeadm -C -n user
kopano-backup --restore user

This did take the better part of a day.

Makes me wonder though, what changed in the last half year or so that caused this corruption/errors, or made z-push/kopano more sensitive? Connecting new devices worked fine a few months ago.

P.S. btrfs filesystem snapshots are a life saver. :-)

rolek

@jengelh Jan, I tried increasing the MariaDB value for max_allowed_packet to 64MB, but that didn’t fix the issue. (This was a few days ago). So I don’t think that’s the cause.

jengelh

That sounds familiar. Synchronization streams will currently abort on error (e.g. attachment strangely missing from database).