6.0.0-git
2019-05-25

[#13825] Remi PHP update to 5.5.21-1 results in constant resyncing
Summary Remi PHP update to 5.5.21-1 results in constant resyncing
Queue Synchronization
Queue Version FRAMEWORK_5_2
Type Bug
State Not A Bug
Priority 1. Low
Owners mrubinsk (at) horde (dot) org
Requester christian (at) hailer (dot) eu
Created 2015-01-23 (1583 days ago)
Due
Updated 2015-02-23 (1552 days ago)
Assigned 2015-01-23 (1583 days ago)
Resolved 2015-02-23 (1552 days ago)
Milestone
Patch No

History
2015-02-23 16:08:28 Michael Rubinsky Comment #28
State ⇒ Not A Bug
Reply to this comment
Closing as this is a PHP issue, not Horde.
2015-02-09 22:39:31 adorman (at) ironicdesign (dot) com Comment #27 Reply to this comment
Agree.  This is the only change which was applied when this problem began.
2015-02-09 19:51:28 Michael Rubinsky Comment #26 Reply to this comment
2015-02-09 17:21:26 adorman (at) ironicdesign (dot) com Comment #25 Reply to this comment
I have run into what appears to be a similar problem with an upgrade 
to PHP 5.6.5 (Debian apparently skipped 5.5.21)

According to our IMAP debug log, Horde is sending the following LIST 
command to Cyrus with the response as shown here:

C: 6 LIST () "" (INBOX * "Other Users/*""" "Shared Folders/*""") 
RETURN (SUBSCRIBED)
S: 6 BAD Invalid syntax in List command

I did some manual IMAP testing and determined that the problem is that 
the LIST command needs a space between the mailbox name like "Other 
Users/*" and the reference name "pattern", in this case "".

In a manual test using openssl to interact with our IMAP server, the 
LIST command below works fine and the only difference is the space 
after the mailbox name:

LIST () "" (INBOX * "Other Users/*" "" "Shared Folders/*" "") RETURN 
(SUBSCRIBED)

Apparently whatever PHP function being used to build the command 
string is no longer adding a space delimiter when adding the empty "".

I would be happy to test a fix if someone could let me know where the 
command string is being assembled.  I have been walking through the 
code in Horde/Imap/Client/ for several hours now and have not been 
able to determine where or how to add that needed space.

Thank you
2015-02-07 08:29:28 christian (at) hailer (dot) ru Comment #24 Reply to this comment
Horde::debug($folder->_toString());
Oh, the output will be placed in a file named horde_debug.txt in 
your temporary directory.
Hello, I'm not available next week, I will try this the week after next week!

Christian
2015-02-05 14:14:33 Michael Rubinsky Comment #23 Reply to this comment
Horde::debug($folder->_toString());
Oh, the output will be placed in a file named horde_debug.txt in your 
temporary directory.
2015-02-05 14:13:55 Michael Rubinsky Comment #22 Reply to this comment
If you could add the following to 
Horde_ActiveSync_Imap_Adapter::getUidFromMid() 
(ActiveSync/Imap/Adapter.php) it might help point me in the right 
direction.

Horde::debug($folder->_toString());

Add this as the first line in the method, so, right before the line 
that reads (this is line 649 locally):

$iids = new Horde_Imap_Client_Ids(array_diff($folder->messages(), 
$folder->removed()));
         $search_q = new Horde_Imap_Client_Search_Query();


2015-02-05 08:21:42 christian (at) hailer (dot) eu Comment #21 Reply to this comment
Furthermore, what is odd is that the OP states this only occurs after
upgrading php to 5.5.21 and downgrading it causes the issue to go
away. I'm currently running 5.5.21 (via macports) with no issue
though.
Agreed - that is odd, especially since nothing substantive has 
changed in the Horde_Imap_Client_Ids object in a year.
Thank you both for looking into this issue!!
As Michael R. said, I can trigger the issue by upgrading PHP to 
5.5.21, and fix it by downgrading to  5.5.20

Here is my server configuration, maybe someone with the same setup can 
reproduce the issue:

CentOS release 6.6 (Final) running on a virtual machine at Strato 
(Virtual Server Linux Level3), using a custom Strato kernel:

2.6.32-042stab092.3 #1 SMP Sun Jul 20 13:27:24 MSK 2014 i686 i686 i386 
GNU/Linux

I'm running the PEAR version, everything is up2date:

Installed packages, channel pear.horde.org:
===========================================
Package                      Version State
Horde_ActiveSync             2.24.0  stable
Horde_Alarm                  2.2.3   stable
Horde_Argv                   2.0.10  stable
Horde_Auth                   2.1.6   stable
Horde_Autoloader             2.1.0   stable
Horde_Browser                2.0.8   stable
Horde_Cache                  2.5.0   stable
Horde_Cli                    2.0.6   stable
Horde_Compress               2.0.8   stable
Horde_Compress_Fast          1.1.0   stable
Horde_Constraint             2.0.2   stable
Horde_Controller             2.0.2   stable
Horde_Core                   2.18.3  stable
Horde_Crypt                  2.5.2   stable
Horde_Crypt_Blowfish         1.0.3   stable
Horde_CssMinify              1.0.2   stable
Horde_Css_Parser             1.0.6   stable
Horde_Data                   2.1.1   stable
Horde_Date                   2.0.13  stable
Horde_Date_Parser            2.0.3   stable
Horde_Dav                    1.1.2   stable
Horde_Db                     2.2.2   stable
Horde_Editor                 2.0.4   stable
Horde_ElasticSearch          1.0.3   stable
Horde_Exception              2.0.5   stable
Horde_Feed                   2.0.3   stable
Horde_Form                   2.0.9   stable
Horde_Group                  2.0.4   stable
Horde_HashTable              1.2.1   stable
Horde_History                2.3.3   stable
Horde_Http                   2.1.3   stable
Horde_Icalendar              2.0.10  stable
Horde_Idna                   1.0.1   stable
Horde_Image                  2.1.0   stable
Horde_Imap_Client            2.26.1  stable
Horde_Imsp                   2.0.6   stable
Horde_Injector               2.0.4   stable
Horde_Itip                   2.0.7   stable
Horde_JavascriptMinify       1.1.2   stable
Horde_JavascriptMinify_Jsmin 1.0.1   stable
Horde_Kolab_Format           2.0.6   stable
Horde_Kolab_Server           2.0.3   stable
Horde_Kolab_Session          2.0.2   stable
Horde_Kolab_Storage          2.1.2   stable
Horde_Ldap                   2.2.0   stable
Horde_ListHeaders            1.2.1   stable
Horde_Lock                   2.1.1   stable
Horde_Log                    2.1.1   stable
Horde_LoginTasks             2.0.4   stable
Horde_Mail                   2.5.1   stable
Horde_Mail_Autoconfig        1.0.2   stable
Horde_Mapi                   1.0.4   stable
Horde_Memcache               2.0.7   stable
Horde_Mime                   2.7.0   stable
Horde_Mime_Viewer            2.0.8   stable
Horde_Mongo                  1.0.3   stable
Horde_Nls                    2.0.5   stable
Horde_Notification           2.0.2   stable
Horde_Oauth                  2.0.2   stable
Horde_OpenXchange            1.0.0   stable
Horde_Pack                   1.0.5   stable
Horde_Pdf                    2.0.4   stable
Horde_Perms                  2.1.3   stable
Horde_Prefs                  2.7.1   stable
Horde_Queue                  1.1.2   stable
Horde_Rdo                    2.0.3   stable
Horde_Role                   1.0.1   stable
Horde_Routes                 2.0.3   stable
Horde_Rpc                    2.1.2   stable
Horde_Scribe                 2.0.2   stable
Horde_Secret                 2.0.4   stable
Horde_Serialize              2.0.3   stable
Horde_Service_Facebook       2.0.7   stable
Horde_Service_Gravatar       1.0.0   stable
Horde_Service_Twitter        2.1.2   stable
Horde_Service_Weather        2.1.5   stable
Horde_SessionHandler         2.2.4   stable
Horde_Share                  2.0.6   stable
Horde_Smtp                   1.8.0   stable
Horde_Socket_Client          1.1.2   stable
Horde_SpellChecker           2.1.2   stable
Horde_Stream                 1.6.2   stable
Horde_Stream_Filter          2.0.3   stable
Horde_Stream_Wrapper         2.1.1   stable
Horde_Stringprep             1.0.1   stable
Horde_Support                2.1.2   stable
Horde_SyncMl                 2.0.5   stable
Horde_Template               2.0.2   stable
Horde_Test                   2.4.8   stable
Horde_Text_Diff              2.1.1   stable
Horde_Text_Filter            2.2.2   stable
Horde_Text_Filter_Csstidy    2.0.1   stable
Horde_Text_Filter_Jsmin      1.0.1   stable
Horde_Text_Flowed            2.0.2   stable
Horde_Thrift                 2.0.2   stable
Horde_Timezone               1.0.9   stable
Horde_Token                  2.0.6   stable
Horde_Translation            2.2.0   stable
Horde_Tree                   2.0.3   stable
Horde_Url                    2.2.4   stable
Horde_Util                   2.5.2   stable
Horde_Vfs                    2.2.1   stable
Horde_View                   2.0.4   stable
Horde_Xml_Element            2.0.2   stable
Horde_Xml_Wbxml              2.0.2   stable
ansel                        3.0.1   stable
content                      2.0.4   stable
gollem                       3.0.3   stable
horde                        5.2.3   stable
horde_lz4                    1.0.7   stable
imp                          6.2.6   stable
ingo                         3.2.3   stable
kronolith                    4.2.4   stable
mnemo                        4.2.3   stable
nag                          4.2.3   stable
passwd                       5.0.2   stable
timeobjects                  2.1.0   stable
trean                        1.1.1   stable
turba                        4.2.4   stable
webmail                      5.2.4   stable
wicked                       2.0.3   stable

For PHP, I'm using the Remi repository (http://rpms.famillecollet.com/):

php-5.5.20-2.el6.remi.i686
php-bcmath-5.5.20-2.el6.remi.i686
php-cli-5.5.20-2.el6.remi.i686
php-common-5.5.20-2.el6.remi.i686
php-devel-5.5.20-2.el6.remi.i686
php-gd-5.5.20-2.el6.remi.i686
php-imap-5.5.20-2.el6.remi.i686
php-ldap-5.5.20-2.el6.remi.i686
php-mbstring-5.5.20-2.el6.remi.i686
php-mysqlnd-5.5.20-2.el6.remi.i686
php-odbc-5.5.20-2.el6.remi.i686
php-pdo-5.5.20-2.el6.remi.i686
php-pecl-apc-3.1.15-0.4.20130912.el6.remi.5.5.i686
php-pecl-imagick-3.1.2-3.el6.remi.5.5.i686
php-pecl-jsonc-1.3.6-1.el6.remi.5.5.1.i686
php-pecl-jsonc-devel-1.3.6-1.el6.remi.5.5.1.i686
php-pecl-zip-1.12.4-1.el6.remi.5.5.i686
php-process-5.5.20-2.el6.remi.i686
php-snmp-5.5.20-2.el6.remi.i686
php-soap-5.5.20-2.el6.remi.i686
php-tidy-5.5.20-2.el6.remi.i686
php-xml-5.5.20-2.el6.remi.i686
php-xmlrpc-5.5.20-2.el6.remi.i686

Best regards,
Christian
2015-02-05 06:02:41 Michael Slusarz Comment #20 Reply to this comment
Furthermore, what is odd is that the OP states this only occurs 
after upgrading php to 5.5.21 and downgrading it causes the issue to 
go away. I'm currently running 5.5.21 (via macports) with no issue 
though.
Agreed - that is odd, especially since nothing substantive has changed 
in the Horde_Imap_Client_Ids object in a year.
2015-02-05 05:44:11 Michael Rubinsky Comment #19 Reply to this comment
Furthermore, what is odd is that the OP states this only occurs after 
upgrading php to 5.5.21 and downgrading it causes the issue to go 
away. I'm currently running 5.5.21 (via macports) with no issue though.
2015-02-05 05:42:05 Michael Rubinsky Comment #18 Reply to this comment
I thought that as well and spent a good bit of time tracing code to 
check.  The uids are in the array values, not the keys, so any 
re-indexing done by array_* functions *shouldn't* cause this type of 
side effect. There is the possibility for an empty array to result 
from some of these array_diff calls, but that's different than an 
array with an element value of zero.  Various debug points I inserted 
seem to confirm this - at least locally.

The other thought I had was something going wrong with 
(un)serialization of the folder object and/or the compressed uid list 
but haven't been able to find any failure mode that results in this.
2015-02-05 05:21:09 Michael Slusarz Comment #17 Reply to this comment

[Show Quoted Text - 12 lines]
Any chance that maybe the array_diff, or something after it, is a 
doing a re-indexing of the ids list (not looking at code, so this is 
just spitballing).  Trying to think of logical ways an array can end 
up having a zero value.
2015-02-04 18:23:18 Michael Rubinsky Comment #16
Taken from Michael M Slusarz <slusarz@horde.org>
Reply to this comment
The only thing I can think of is that this is a secondary effect to 
the STATUS error, since the HIGHESTMODSEQ value returned from that 
call is used to determine if we need to treat the server as 
MODSEQ/CONDSTORE capable or not. If a server that has been treated 
as MODSEQ is suddenly treated as not, that will cause all sorts of 
issues with UID handling since we store different data structures 
for each.
Actually, this wouldn't be the case since if the STATUS call fails (as 
it seems to be doing here), the code simply throws an exception and 
stops processing the request. So something else might be going on here.
2015-02-04 18:00:16 Michael Rubinsky Comment #15 Reply to this comment
C: 31 UID SEARCH RETURN (ALL COUNT) HEADER MESSAGE-ID
<00d701d01f08$6f76a3f0$4e63ebd0$@amusing.de> UID 0:215
S: 31 BAD Error in IMAP command UID SEARCH: Invalid UID messageset
Obviously, 0 is not allowed.  Imap code doesn't do assert checking 
for this situation (it probably should).  But that 0 has to come 
from the calling code.
I can't reproduce this. The ids provided to the method that calls this 
search routine come from the list of uids provided from the IMAP 
server. There is an array_diff that removes uids that we know have 
since vanished. The only thing I can think of is that this is a 
secondary effect to the STATUS error, since the HIGHESTMODSEQ value 
returned from that call is used to determine if we need to treat the 
server as MODSEQ/CONDSTORE capable or not. If a server that has been 
treated as MODSEQ is suddenly treated as not, that will cause all 
sorts of issues with UID handling since we store different data 
structures for each.

I can add code to attempt to detect this "switch", but it won't solve 
the underlying problem and will only cause things to fail in a 
different, more controlled way.

[Show Quoted Text - 12 lines]
I can't reproduce either. Not in ActiveSync unit testing, local client 
testing, or IMP/IMAP testing.  You are going to need to figure out 
where the extra quotes are coming from in the mailbox name. As a 
start, you can try running the following code in Horde's PHP shell 
(Administration->PHPSHELL):

$f = new Horde_Core_ActiveSync_Imap_Factory();
var_dump($f->getMailboxes(true));

and see what type or values are returned.
2015-02-03 01:54:47 Michael Slusarz Comment #14 Reply to this comment
C: 31 UID SEARCH RETURN (ALL COUNT) HEADER MESSAGE-ID 
<00d701d01f08$6f76a3f0$4e63ebd0$@amusing.de> UID 0:215
S: 31 BAD Error in IMAP command UID SEARCH: Invalid UID messageset
Obviously, 0 is not allowed.  Imap code doesn't do assert checking for 
this situation (it probably should).  But that 0 has to come from the 
calling code.
C: 31 STATUS "INBOX.!  Astrid""" (MESSAGES UIDNEXT UIDVALIDITY HIGHESTMODSEQ)
Can't reproduce.  I have no idea where those extra quotes are coming 
from, since if they actually did exist in the input they would be 
escaped.

Considering that nothing has changed in regards to either Id 
generation or String escaping lately, this doesn't seem to be anything 
related to Imap_Client code.  (Whitespace is irrelevant - I have 
hundreds of mailboxes with whitespace and they display perfectly fine.)
2015-02-03 01:54:38 Git Commit Comment #13 Reply to this comment
Changes have been made in Git (master):

commit 462c7a01841357f6214bd12e891f6383ee3b58bf
Author: Michael M Slusarz <slusarz@horde.org>
Date:   Mon Feb 2 18:53:51 2015 -0700

     Passing unit tests for Bug #13825

  .../test/Horde/Imap/Client/MailboxTest.php         |   28 
++++++++++++++++++++
  1 files changed, 28 insertions(+), 0 deletions(-)

http://github.com/horde/horde/commit/462c7a01841357f6214bd12e891f6383ee3b58bf
2015-02-02 15:15:34 Michael Rubinsky Assigned to Michael M Slusarz <slusarz@horde.org>
Assigned to Michael Rubinsky
 
2015-02-02 08:04:11 christian (at) hailer (dot) eu Comment #12 Reply to this comment
Michael S., can you weigh in here?
Hello Michael S.,

did you have the chance to have a look into it?

Best regards, Christian
2015-01-26 14:32:11 Michael Rubinsky Comment #11 Reply to this comment
Michael S., can you weigh in here?
2015-01-26 07:28:49 christian (at) hailer (dot) eu Comment #10
New Attachment: horde_imp_debug.log Download
Reply to this comment
OK, I updated PHP this morning and had a look at the IMAP debug log. 
Here are 2 examples:

C: 31 UID SEARCH RETURN (ALL COUNT) HEADER MESSAGE-ID 
<00d701d01f08$6f76a3f0$4e63ebd0$@amusing.de> UID 0:215
S: 31 BAD Error in IMAP command UID SEARCH: Invalid UID messageset
Command 31 took 0,0008 seconds.
and

C: 31 STATUS "INBOX.!  Astrid""" (MESSAGES UIDNEXT UIDVALIDITY HIGHESTMODSEQ)
S: 31 BAD Error in IMAP command STATUS: Invalid arguments.
Command 31 took 0.0012 seconds.
The second error only occurs for folders containing whitespaces.

Afterwards the IMAP errors show in the ActiveSync log:

2015-01-26T07:21:28+01:00 INFO: [936] Initializing state for 
collection: INBOX.!  Astrid, synckey: 
{54854e18-3c50-4b6c-9de1-2bfd51a9e6c4}455
...
2015-01-26T07:21:28+01:00 WARN: [936] FOLDERSYNC required, collection gone.
...
2015-01-26T07:21:28+01:00 INFO: [936] Initializing state for 
collection: INBOX.Pound, synckey: 
{54854e18-04b4-49b8-95c0-2bfd51a9e6c4}207
...
2015-01-26T07:21:28+01:00 ERR: IMAP error reported by server.
...

The first error seems to occur only for messages with a UID starting 
with "0:", because this search worked:

C: 18 UID SEARCH RETURN (ALL COUNT) HEADER MESSAGE-ID 
<urn.rtn.msg.2015012317455385c863f6a3a546d380bc665834c256d9@1422035154979.rte-svc-eu-1abig-i-18852b52.eu-west-1.amazon.com> UID 
6515:6680
S: * ESEARCH (TAG "18") UID COUNT 0
S: 18 OK Search completed (0.000 secs).
Command 18 took 0.0043 seconds.
I attached the log.

Regards, Christian
2015-01-24 22:01:02 arjen+horde (at) de-korte (dot) org Comment #9 Reply to this comment
This would be the proper configuriation, right?

$servers['imap'] = array(
      'disabled' => false,
      'debug' => '/var/log/horde_imp_debug.log',
No. You're either modifying 'imp/config/backends.php' (which you 
should never do, since changes will be lost on updates) or are 
redefining $server['imap'] in 'imp/config/backends.local.php' (which 
you shouldn't do either, since this will also remove additional 
parameters on updates).

The correct method would be to put the following in 
'imp/config/backends.local.php':

     <?php
     $servers['imap']['disabled'] = true;
     $servers['imap']['debug'] = '/var/log/horde_imp_debug.log';
2015-01-24 21:03:32 christian (at) hailer (dot) eu Comment #8 Reply to this comment
I just had a look at my dovecot log and the dovecot error log, there
are no log entries referring to some kind of error...
These aren't the logs I asked for. You need to enable IMAP debug 
logging in IMP and look at the imap client library log.
Ah sorry, I'll try that next week.

This would be the proper configuriation, right?

$servers['imap'] = array(
      'disabled' => false,
      'debug' => '/var/log/horde_imp_debug.log',
...

Thank you!
2015-01-24 18:57:25 Michael Rubinsky Comment #7 Reply to this comment
I just had a look at my dovecot log and the dovecot error log, there 
are no log entries referring to some kind of error...
These aren't the logs I asked for. You need to enable IMAP debug 
logging in IMP and look at the imap client library log.
2015-01-24 16:18:08 christian (at) hailer (dot) eu Comment #6 Reply to this comment
I just had a look at my dovecot log and the dovecot error log, there 
are no log entries referring to some kind of error...

If you have a look at the PHP changelog, is there anything which could 
affect the Horde-Dovecot connection being established by your 
connector? ( http://php.net/ChangeLog-5.php#5.5.21 )

22 Jan 2015

     Core:
         Upgraded crypt_blowfish to version 1.3
         Fixed bug #60704 (unlink() bug with some files path).
         Fixed bug #65419 (Inside trait, self::class != __CLASS__).
         Fixed bug #65576 (Constructor from trait conflicts with 
inherited constructor).
         Fixed bug #55541 (errors spawn MessageBox, which blocks test 
automation).
         Fixed bug #68297 (Application Popup provides too few information).
         Fixed bug #65769 (localeconv() broken in TS builds).
         Fixed bug #65230 (setting locale randomly broken).
         Fixed bug #66764 (configure doesn't define EXPANDED_DATADIR / 
PHP_DATADIR correctly).
         Fixed bug #68583 (Crash in timeout thread).
         Fixed bug #68676 (Explicit Double Free).
         Fixed bug #68710 (Use After Free Vulnerability in PHP's 
unserialize()).(CVE-2015-0231).
     CGI:
         Fixed bug #68618 (out of bounds read crashes php-cgi).(CVE-2014-9427).
     CLI server:
         Fixed bug #68745 (Invalid HTTP requests make web server segfault).
     cURL:
         Fixed bug #67643 (curl_multi_getcontent returns '' when 
CURLOPT_RETURNTRANSFER isn't set).
     EXIF:
         Fixed bug #68799 (Free called on unitialized pointer). (CVE-2015-0232)
     Fileinfo:
         Fixed bug #68671 (incorrect expression in libmagic).
         Fixed bug #68735 (fileinfo out-of-bounds memory access).
         Removed readelf.c and related code from libmagic sources
     FPM:
         Fixed bug #68751 (listen.allowed_clients is broken).
     GD:
         Fixed bug #68601 (buffer read overflow in gd_gif_in.c).
     Mbstring:
         Fixed bug #68504 (--with-libmbfl configure option not present 
on Windows).
     Mcrypt:
         Fixed possible read after end of buffer and use after free.
     Opcache:
         Fixed bug #67111 (Memory leak when using "continue 2" inside 
two foreach loops).
     Pcntl:
         Fixed bug #60509 (pcntl_signal doesn't decrease ref-count of 
old handler when setting SIG_DFL).
     PCRE:
         Fixed bug #66679 (Alignment Bug in PCRE 8.34 upstream).
     pgsql:
         Fixed bug #68697 (lo_export return -1 on failure).
     PDO:
         Fixed bug #68371 (PDO#getAttribute() cannot be called with 
platform-specific attribute names).
     PDO_mysql:
         Fixed bug #68424 (Add new PDO mysql connection attr to 
control multi statements option).
     SPL:
         Fixed bug #66405 
(RecursiveDirectoryIterator::CURRENT_AS_PATHNAME breaks the 
RecursiveIterator).
         Fixed bug #65213 (cannot cast SplFileInfo to boolean).
         Fixed bug #68479 (Added escape parameter to SplFileObject::fputcsv).
     SQLite:
         Fixed bug #68120 (Update bundled libsqlite to 3.8.7.2).
     Streams:
         Fixed bug #68532 (convert.base64-encode omits padding bytes).

Best regards, Christian
2015-01-23 16:25:51 Michael Rubinsky Comment #5 Reply to this comment
2015-01-23T09:00:07+01:00 INFO: [29742] INBOX.!  Astrid IMAP MODSEQ: 1431
2015-01-23T09:00:07+01:00 ERR: IMAP error reported by server.
  >If it's the status command, from ActiveSync's point of
view it will look like the folder is gone, so the state will be 
removed - thus triggering the resync.
Looking at your log again, this is exactly what is happening. The 
first log entry above occurs when first checking horde's driver for 
changes - immediately after that should be a log entry showing the 
results of the IMAP status command, which is missing in your log. 
That's what is causing the error. You just need to get the IMAP server 
log to find out the actual error being returned.
2015-01-23 16:16:59 Michael Rubinsky Comment #4 Reply to this comment
2015-01-23T09:00:07+01:00 INFO: [29742] INBOX.!  Astrid IMAP MODSEQ: 1431
2015-01-23T09:00:07+01:00 ERR: IMAP error reported by server.
This error is reported directly from Horde_Imap_Client. It typically 
means the IMAP server returned a NO, or BAD or similar response. I.e., 
an error. I still can't tell what command is triggering the IMAP 
error. If it's the status command, from ActiveSync's point of view it 
will look like the folder is gone, so the state will be removed - thus 
triggering the resync.

You should enable IMAP debug logging (see imp/config/backends.php for 
how to do this) so we can see what IMAP command is causing the trouble.

2015-01-23 15:02:22 christian (at) hailer (dot) eu Comment #3 Reply to this comment

[Show Quoted Text - 11 lines]
Hello Michael,

no, there are no errors in any other logs, none in Apache, Dovecot, 
normal Horde log...

[Show Quoted Text - 17 lines]
here is a part of the sync log:

2015-01-23T09:00:07+01:00 INFO: [29742] Initializing state for 
collection: INBOX.!  Astrid, synckey: 
{54854e18-3c50-4b6c-9de1-2bfd51a9e6c4}455
2015-01-23T09:00:07+01:00 INFO: [29742] Loading state for synckey 
{54854e18-3c50-4b6c-9de1-2bfd51a9e6c4}455
2015-01-23T09:00:07+01:00 INFO: [29742] Initializing message diff 
engine for F0eb0762a (INBOX.!  Astrid)
2015-01-23T09:00:07+01:00 INFO: [29742] 
Horde_Core_ActiveSync_Driver::getSyncStamp(INBOX.!  Astrid, 1421928788);
2015-01-23T09:00:07+01:00 INFO: [29742] Using SYNCSTAMP 1422000007 for 
F0eb0762a.
2015-01-23T09:00:07+01:00 INFO: [29742] 
Horde_Core_ActiveSync_Driver::getServerChanges(INBOX.!  Astrid, 
1421928788, 1422000007, 0, 1, 1, 100, )
2015-01-23T09:00:07+01:00 INFO: [29742] INBOX.!  Astrid IMAP MODSEQ: 1431
2015-01-23T09:00:07+01:00 ERR: IMAP error reported by server.
2015-01-23T09:00:08+01:00 INFO: [29742] Found 0 message changes in F0eb0762a.

Some minutes later when the IMAP error is gone it's resyncing the folder:

2015-01-23T09:05:34+01:00 INFO: [29782] Initializing state for 
collection: INBOX.!  Astrid, synckey: 
{54854e18-3c50-4b6c-9de1-2bfd51a9e6c4}455
2015-01-23T09:05:34+01:00 INFO: [29782] Loading state for synckey 
{54854e18-3c50-4b6c-9de1-2bfd51a9e6c4}455
2015-01-23T09:05:34+01:00 INFO: [29782] Initializing message diff 
engine for F0eb0762a (INBOX.!  Astrid)
2015-01-23T09:05:34+01:00 INFO: [29782] 
Horde_Core_ActiveSync_Driver::getSyncStamp(INBOX.!  Astrid, 1421928788);
2015-01-23T09:05:34+01:00 INFO: [29782] Using SYNCSTAMP 1422000334 for 
F0eb0762a.
2015-01-23T09:05:34+01:00 INFO: [29782] 
Horde_Core_ActiveSync_Driver::getServerChanges(INBOX.!  Astrid, 
1421928788, 1422000334, 0, 0, 1, 100, )
2015-01-23T09:05:34+01:00 INFO: [29782] INBOX.!  Astrid IMAP MODSEQ: 1431
2015-01-23T09:05:34+01:00 WARN: [29782] FOLDERSYNC required, collection gone.
2015-01-23T09:05:34+01:00 DEBUG: [29782] O    <Folder>
2015-01-23T09:05:34+01:00 DEBUG: [29782] O     <SyncKey>
2015-01-23T09:05:34+01:00 DEBUG: [29782] O       
{54854e18-3c50-4b6c-9de1-2bfd51a9e6c4}455
2015-01-23T09:05:34+01:00 DEBUG: [29782] O     </SyncKey>
2015-01-23T09:05:34+01:00 DEBUG: [29782] O     <FolderId>
2015-01-23T09:05:34+01:00 DEBUG: [29782] O      F0eb0762a
2015-01-23T09:05:34+01:00 DEBUG: [29782] O     </FolderId>
2015-01-23T09:05:34+01:00 DEBUG: [29782] O     <Status>
2015-01-23T09:05:34+01:00 DEBUG: [29782] O      12
2015-01-23T09:05:34+01:00 DEBUG: [29782] O     </Status>
2015-01-23T09:05:34+01:00 DEBUG: [29782] O    </Folder>


2015-01-23 14:46:38 Michael Rubinsky Comment #2
State ⇒ Feedback
Reply to this comment
Then I realized I updated PHP and that the php-imap package was 
among the updates. I downgraded all PHP packages to the old version 
and everything works like a charm now.
Horde/IMP does not make use of the PHP bundled IMAP library. We use 
our own Horde_Imap_Client library. If this issue is, in fact, due to a 
PHP update, it is not from php-imap. Any other errors in the webserver 
error log, or the horde log?
The reason why I'm filing this bug is: I think Horde should handle 
the above error message and tell the ActiveSync client to try again 
later. I suspect that Horde reported back to the client that no 
message at all is left in the folder it tried to sync when the error 
occurs, and with the next ping it is able to connect again and 
resyncs all the messages.
Normally, when an error such as the one you describe occurs, we report 
the error condition back to the client (as we should). What the client 
chooses to do with that information is out of our control. I'd have to 
see more context in the sync log to see if we are sending the most 
appropriate error code back or not. Depending on when the error 
occurs, and what the actual error is, we might not have the chance to 
send an error code back. Again, would need to see more context to know 
for sure.


2015-01-23 13:28:53 christian (at) hailer (dot) eu Comment #1
Type ⇒ Bug
State ⇒ Unconfirmed
Priority ⇒ 1. Low
Summary ⇒ Remi PHP update to 5.5.21-1 results in constant resyncing
Queue ⇒ Synchronization
Milestone ⇒
Patch ⇒ No
Reply to this comment
Hello,

I'm not quite sure it's a bug, but I'll describe what happened today 
after updating the Remi PHP packages from version 5.5.20-2 to 5.5.21-1 
(http://php.net/ChangeLog-5.php#5.5.21 and 
http://blog.famillecollet.com/post/2015/01/23/PHP-version-5.4.37-5.5.21-and-5.6.5).

Server: CentOS 6.6 i686

Among others, the php-imap package was updated this morning. Several 
friends contacted me some hours later to tell me their ActiveSync 
devices are syncing constantly, emptying the folders and resyncing 
again. It affected all device types, Outlook 2013, Android and iPhone.
I had a look at the Horde ActiveSync device logs and saw a lot of 
errors like this these:

2015-01-23T13:45:21+01:00 ERR: IMAP error reported by server.
2015-01-23T13:45:21+01:00 ERR: IMAP error reported by server.
2015-01-23T13:45:36+01:00 ERR: IMAP error reported by server.
2015-01-23T13:45:36+01:00 ERR: IMAP error reported by server.
2015-01-23T13:45:36+01:00 ERR: IMAP error reported by server.
2015-01-23T13:45:36+01:00 ERR: IMAP error reported by server.
2015-01-23T13:45:36+01:00 ERR: IMAP error reported by server.

So I had a look at dovecot which I use as the IMAP backend. No 
problems/errors in the logs.

Then I realized I updated PHP and that the php-imap package was among 
the updates. I downgraded all PHP packages to the old version and 
everything works like a charm now.

The reason why I'm filing this bug is: I think Horde should handle the 
above error message and tell the ActiveSync client to try again later. 
I suspect that Horde reported back to the client that no message at 
all is left in the folder it tried to sync when the error occurs, and 
with the next ping it is able to connect again and resyncs all the 
messages.

Could that be the reason for the above behaviour?

Best regards, Christian

Saved Queries