6.0.0-git
2020-01-18

[#14972] AcitveSync is not longer working properly after PHP upgrade to 7.3 -> mailbox subfolders are show as empty via EAS & Outlook 365
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 Feedback
Priority 1. Low
Owners mrubinsk (at) horde (dot) org
Requester torben (at) dannhauer (dot) info
Created 2019-12-23 (26 days ago)
Due
Updated 2019-12-25 (24 days ago)
Assigned 2019-12-23 (26 days ago)
Resolved
Milestone
Patch No

History
2019-12-25 14:03:49 torben (at) dannhauer (dot) info Comment #7 Reply to this comment
Indeed, fixing max_input_time fixed the issue.

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
2019-12-23 20:42:14 torben (at) dannhauer (dot) info Comment #6 Reply to this comment
Fast reaction times, great performance!

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!
2019-12-23 19:50:09 Michael Rubinsky Comment #5
Priority ⇒ 1. Low
Reply to this comment
The PHP 7.3 related WARNING entries in the log have been fixed.

Feel free to post relevant portions of your activesync log for further help.
2019-12-23 18:45:35 build+horde (at) de-korte (dot) org Comment #4 Reply to this comment
For what it's worth, I've been running PHP 7.3 for quite a while 
with no issues.
I've been running Horde with PHP 7.4 for a little over a month now, 
with no issues either.
2019-12-23 17:42:29 Michael Rubinsky Assigned to Michael Rubinsky
State ⇒ Feedback
 
2019-12-23 17:41:08 Michael Rubinsky Comment #3 Reply to this comment
---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"]
This is harmless, though should be fixed. It's a logging statement 
that assumes an array is set when it's possible it might not be.
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"]
Your logs have multiple entries like this. This seems fishy to me. I 
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.
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"]
This one confuses me, as the code path that leads to this line should 
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.

[Show Quoted Text - 12 lines]
These are expected from time to time. This occurs when ActiveSync 
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.


2019-12-23 16:27:59 build+horde (at) de-korte (dot) org Comment #2 Reply to this comment
This has nothing to do with the upgrade to PHP 7.3. It is the below 
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.
2019-12-23 12:24:48 torben (at) dannhauer (dot) info Comment #1
Type ⇒ Bug
State ⇒ Unconfirmed
Priority ⇒ 2. Medium
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
Milestone ⇒
Patch ⇒ No
Reply to this comment
Hi,

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---


Saved Queries