[Tickets #14972] Re: AcitveSync is not longer working properly after PHP upgrade to 7.3 -> mailbox subfolders are show as empty via EAS & Outlook 365

[noreply at bugs.horde.org]

DO NOT REPLY TO THIS MESSAGE. THIS EMAIL ADDRESS IS NOT MONITORED.

Ticket URL: https://bugs.horde.org/ticket/14972
------------------------------------------------------------------------------
  Ticket             | 14972
  Updated By         | Michael Rubinsky <mrubinsk at horde.org>
  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
  Version            | FRAMEWORK_5_2
  Type               | Bug
  State              | Unconfirmed
  Priority           | 2. Medium
  Milestone          |
  Patch              |
  Owners             |
------------------------------------------------------------------------------


Michael Rubinsky <mrubinsk at horde.org> (2019-12-23 17:41) wrote:


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


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

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.