Summary |
AcitveSync is not longer working properly after PHP upgrade to 7.3 -> mailbox subfolders are show as empty via EAS & Outlook 365 |
Queue |
Synchronization |
Queue Version |
FRAMEWORK_5_2 |
Type |
Bug |
State |
Resolved |
Priority |
1. Low |
Owners |
mrubinsk (at) horde (dot) org |
Requester |
torben (at) dannhauer (dot) info |
Created |
12/23/2019 (2016 days ago) |
Due |
|
Updated |
02/24/2020 (1953 days ago) |
Assigned |
12/23/2019 (2016 days ago) |
Resolved |
02/24/2020 (1953 days ago) |
Github Issue Link |
|
Github Pull Request |
|
Milestone |
|
Patch |
No |
Is max_execution_time and max_input_time tested/mentioned/proposed in
test.php? Maybe a chance to reduce uneccessary bugreports like this :)
Sorry for the noise again.
Regards,
Torben
Thanks for the code cleanup, makes it asier to hunt.
The issue could be a PEBKAC : I was not aware of the max_input_time
configuration. It seems my PHP upgrade also introduced a new default
value which is no longer -1, but a (too short) time period.
Currently I try to reproduce the error on a differnet machine, there
it looks good now.
I'll verify it on 25th Dec as soon as a have access again to the
problematic machine. I'll be back :)
So far: Merry Christmas!
Priority ⇒ 1. Low
Feel free to post relevant portions of your activesync log for further help.
with no issues.
with no issues either.
Assigned to Michael Rubinsky
2019-12-22T18:33:12+01:00 WARN: HORDE PHP ERROR: count(): Parameter
must be an array or an object that implements Countable [pid 28532
on line 371 of "/usr/share/php/Horde/ActiveSync/State/Sql.php"]
that assumes an array is set when it's possible it might not be.
seconds exceeded [pid 30661 on line 76 of
"/usr/share/php/Horde/Support/CaseInsensitiveArray.php"]
remember there was some isssue a while back where this was being
reported but really referred to another setting, like max_input_time
instead. No clue if this is relevant to what you are seeing though,
it's possible seeing how some of these are thrown on IMAP related
commands in your log.
must be an array or an object that implements Countable [pid 1226 on
line 3500 of "/usr/share/php/Horde/Core/ActiveSync/Driver.php"]
ensure that the variable is always an array. I'll have to look at this
a bit more. However, this part of the code is related to searching for
contacts, and has nothing to do with mailboxes.
thinks it successfully processes a request and sends the request to
the client with a new synckey, but the client, for whatever reason
does not receive or accept the response. It then uses the same synckey
in the next request, and when then server processes the request and
saves the state, it collides with the synckey from the last try. If
you look at your activesync log you 'll see a message after this that
says something like "trying again".
When this happens frequently, it usually means there is some uncaught
error in the sync process that leads to unexpected data being sent to
the client. Looking at your synclog should shed more light on this.
For what it's worth, I've been running PHP 7.3 for quite a while with
no issues.
error that causes the problem:
HORDE SQL QUERY FAILED: SQLSTATE[23505]: Unique violation: 7 FEHLER:
doppelter Schlüsselwert verletzt Unique-Constraint
»horde_activesync_state_pkey«
You need to resync the account to fix this.
Priority ⇒ 2. Medium
State ⇒ Unconfirmed
Patch ⇒ No
Milestone ⇒
Queue ⇒ Synchronization
Summary ⇒ AcitveSync is not longer working properly after PHP upgrade to 7.3 -> mailbox subfolders are show as empty via EAS & Outlook 365
Type ⇒ Bug
I upgraded my PHP to 7.3.
Now ActiveSync is not longer workling corrctly with Outlook 365, It
seems to be related.
I looked in the Horde log and lots of this errors:
---snip---
2019-12-22T18:33:12+01:00 WARN: HORDE PHP ERROR: count(): Parameter
must be an array or an object that implements Countable [pid 28532 on
line 371 of "/usr/share/php/Horde/ActiveSync/State/Sql.php"]
2019-12-22T18:33:13+01:00 WARN: HORDE PHP ERROR: count(): Parameter
must be an array or an object that implements Countable [pid 28532 on
line 371 of "/usr/share/php/Horde/ActiveSync/State/Sql.php"]
2019-12-22T18:33:13+01:00 WARN: HORDE PHP ERROR: count(): Parameter
must be an array or an object that implements Countable [pid 28532 on
line 371 of "/usr/share/php/Horde/ActiveSync/State/Sql.php"]
2019-12-22T18:43:40+01:00 EMERG: HORDE Maximum execution time of 0
seconds exceeded [pid 30661 on line 76 of
"/usr/share/php/Horde/Support/CaseInsensitiveArray.php"]
2019-12-22T20:28:23+01:00 WARN: HORDE PHP ERROR: count(): Parameter
must be an array or an object that implements Countable [pid 1226 on
line 3500 of "/usr/share/php/Horde/Core/ActiveSync/Driver.php"]
2019-12-22T20:28:25+01:00 WARN: HORDE PHP ERROR: count(): Parameter
must be an array or an object that implements Countable [pid 2128 on
line 3500 of "/usr/share/php/Horde/Core/ActiveSync/Driver.php"]
2019-12-22T22:36:06+03:00 WARN: HORDE PHP ERROR: count(): Parameter
must be an array or an object that implements Countable [pid 4239 on
line 3500 of "/usr/share/php/Horde/Core/ActiveSync/Driver.php"]
2019-12-22T22:36:08+03:00 WARN: HORDE PHP ERROR: count(): Parameter
must be an array or an object that implements Countable [pid 24965 on
line 3500 of "/usr/share/php/Horde/Core/ActiveSync/Driver.php"]
2019-12-22T21:16:35+01:00 ERR: HORDE SQL QUERY FAILED:
SQLSTATE[23505]: Unique violation: 7 FEHLER: doppelter Schlüsselwert
verletzt Unique-Constraint »horde_activesync_state_pkey«
DETAIL: Schlüssel
»(sync_key)=({59e8ac5e-5828-467f-980e-042788f3a8e7}15728)« existiert
bereits.
INSERT INTO "horde_activesync_state" ("sync_key", "sync_data",
"sync_devid", "sync_mod", "sync_folderid", "sync_user",
"sync_pending", "sync_timestamp") VALUES (?, :binary0, ?,
?, ?, ?, ?,
?) [pid 17580 on line 282 of
"/usr/share/php/Horde/Db/Adapter/Pdo/Base.php"]
2019-12-22T21:16:35+01:00 ERR: HORDE SQL QUERY FAILED:
SQLSTATE[23505]: Unique violation: 7 FEHLER: doppelter Schlüsselwert
verletzt Unique-Constraint »horde_activesync_state_pkey«
DETAIL: Schlüssel
»(sync_key)=({59e8ac5e-79b8-4f6a-a6b0-042788f3a8e7}7598)« existiert
bereits.
INSERT INTO "horde_activesync_state" ("sync_key", "sync_data",
"sync_devid", "sync_mod", "sync_folderid", "sync_user",
"sync_pending", "sync_timestamp") VALUES (?, :binary0, ?,
?, ?, ?, ?,
?) [pid 17580 on line 282 of
"/usr/share/php/Horde/Db/Adapter/Pdo/Base.php"]
2019-12-22T21:16:50+01:00 ERR: HORDE SQL QUERY FAILED:
SQLSTATE[23505]: Unique violation: 7 FEHLER: doppelter Schlüsselwert
verletzt Unique-Constraint »horde_activesync_state_pkey«
DETAIL: Schlüssel
»(sync_key)=({59e8ac60-1a64-4d55-8079-042788f3a8e7}1761)« existiert
bereits.
INSERT INTO "horde_activesync_state" ("sync_key", "sync_data",
"sync_devid", "sync_mod", "sync_folderid", "sync_user",
"sync_pending", "sync_timestamp") VALUES (?, :binary0, ?,
?, ?, ?, ?,
?) [pid 18345 on line 282 of
"/usr/share/php/Horde/Db/Adapter/Pdo/Base.php"]
2019-12-22T22:04:15+01:00 EMERG: HORDE Maximum execution time of 0
seconds exceeded [pid 28422 on line 182 of
"/usr/share/php/Horde/String.php"]
2019-12-22T23:04:59+01:00 EMERG: HORDE Maximum execution time of 0
seconds exceeded [pid 12229 on line 327 of
"/usr/share/php/Horde/Db/Adapter/Base/Column.php"]
2019-12-23T01:03:25+01:00 EMERG: HORDE Maximum execution time of 0
seconds exceeded [pid 4559 on line 211 of
"/usr/share/php/Horde/Core/Log/Object.php"]
2019-12-23T02:05:23+01:00 EMERG: HORDE Maximum execution time of 0
seconds exceeded [pid 9844 on line 1724 of
"/usr/share/php/Horde/Imap/Client/Base.php"]
2019-12-23T03:05:13+01:00 EMERG: HORDE Maximum execution time of 0
seconds exceeded [pid 26199 on line 216 of
"/usr/share/php/Horde/String.php"]
2019-12-23T04:05:14+01:00 EMERG: HORDE Maximum execution time of 0
seconds exceeded [pid 11327 on line 53 of
"/usr/share/php/Horde/Imap/Client/Socket/Connection/Socket.php"]
2019-12-23T05:05:06+01:00 EMERG: HORDE Maximum execution time of 0
seconds exceeded [pid 30133 on line 651 of
"/usr/share/php/Horde/Imap/Client/Base.php"]
2019-12-23T06:39:46+01:00 EMERG: HORDE Maximum execution time of 0
seconds exceeded [pid 30104 on line 218 of
"/usr/share/php/Horde/String.php"]
---snip---