Bug: 12316

thnx

but no Success...

Device still not Syncing... and pending in a "Sync-Loop" think its not 
a "ping-loop"

But there are 2 new unread-messages....


2013-06-12T10:48:39+00:00 INFO: [8185] 
Horde_Core_ActiveSync_Driver::getServerChanges(INBOX, 1371033983, 
1371034119,
1370774919, 0)
2013-06-12T10:48:39+00:00 INFO: IMAP status: Array
(
     [uidnext] => 4170
     [uidvalidity] => 1363989728
     [highestmodseq] => 0
)

2013-06-12T10:48:39+00:00 INFO: NO CONDSTORE or per mailbox MODSEQ: minuid=0
2013-06-12T10:48:40+00:00 ERR: Unknown message.
2013-06-12T10:48:40+00:00 INFO: [8185] Found 0 message changes in e69516cf.
2013-06-12T10:48:40+00:00 DEBUG: [8185] O   <Folders>
2013-06-12T10:48:40+00:00 DEBUG: [8185] O    <Folder>
2013-06-12T10:48:40+00:00 DEBUG: [8185] O     <SyncKey>
2013-06-12T10:48:40+00:00 DEBUG: [8185] O       
{51b84b58-a378-4c6e-beb0-202855196ca0}519
2013-06-12T10:48:40+00:00 DEBUG: [8185] O     </SyncKey>
2013-06-12T10:48:40+00:00 DEBUG: [8185] O     <FolderId>
2013-06-12T10:48:40+00:00 DEBUG: [8185] O      e69516cf
2013-06-12T10:48:40+00:00 DEBUG: [8185] O     </FolderId>
2013-06-12T10:48:40+00:00 DEBUG: [8185] O     <Status>
2013-06-12T10:48:40+00:00 DEBUG: [8185] O      1
2013-06-12T10:48:40+00:00 DEBUG: [8185] O     </Status>
2013-06-12T10:48:40+00:00 DEBUG: [8185] O    </Folder>
2013-06-12T10:48:40+00:00 DEBUG: [8185] O   </Folders>
2013-06-12T10:48:40+00:00 DEBUG: [8185] O  </Synchronize>

2013-06-12T10:48:40+00:00 INFO: [8185] Replacing SYNC_CACHE entry for 
user info@slater.be and device APPLDNQKMP4WDTWD
: 
a:11:{s:18:"confirmed_synckeys";a:0:{}s:17:"lasthbsyncstarted";i:1371033982;s:17:"lastsyncendnormal";i:1371034120;s
:9:"timestamp";s:10:"1371034120";s:4:"wait";b:0;s:10:"hbinterval";b:0;s:7:"folders";a:13:{s:8:"f861f7a2";a:2:{s:5:"cl
ass";s:5:"Email";s:8:"serverid";s:15:"INBOX.Gelöscht";}s:8:"e69516cf";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:5
:"INBOX";}s:8:"a99ee508";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:12:"INBOX.Drafts";}s:8:"a7336991";a:2:{s:5:"cl
ass";s:5:"Email";s:8:"serverid";s:13:"INBOX.Entwurf";}s:7:"@Tasks@";a:2:{s:5:"class";s:5:"Tasks";s:8:"serverid";s:7:"
@Tasks@";}s:7:"@Notes@";a:2:{s:5:"class";s:5:"Notes";s:8:"serverid";s:7:"@Notes@";}s:10:"@Contacts@";a:2:{s:5:"class"
;s:8:"Contacts";s:8:"serverid";s:10:"@Contacts@";}s:10:"@Calendar@";a:2:{s:5:"class";s:8:"Calendar";s:8:"serverid";s:
10:"@Calendar@";}s:8:"5d512eef";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:11:"INBOX.Trash";}s:8:"31b8bb24";a:2:{s
:5:"class";s:5:"Email";s:8:"serverid";s:10:"INBOX.Spam";}s:8:"25b84740";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s
:22:"INBOX.Spam.UnLearnSpam";}s:8:"23037e45";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:20:"INBOX.Spam.LearnSpam";
}s:8:"0535ef16";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:10:"INBOX.Sent";}}s:9:"hierarchy";s:39:"{51b84b56-11fc-
496a-8264-200155196ca0}1";s:11:"collections";a:4:{s:10:"@Calendar@";a:11:{s:5:"class";s:8:"Calendar";s:10:"windowsize
";s:2:"25";s:10:"filtertype";s:1:"5";s:10:"truncation";i:0;s:11:"mimesupport";i:0;s:14:"mimetruncation";i:8;s:8:"conf
lict";i:1;s:9:"bodyprefs";a:1:{i:1;a:2:{s:4:"type";s:1:"1";s:14:"truncationsize";s:5:"32768";}}s:8:"serverid";s:10:"@
Calendar@";s:11:"lastsynckey";s:39:"{51b84b58-407c-48e4-802c-202c55196ca0}2";s:8:"pingable";b:1;}s:8:"e69516cf";a:11:
{s:5:"class";s:5:"Email";s:10:"windowsize";s:2:"25";s:10:"filtertype";s:1:"2";s:10:"truncation";i:0;s:11:"mimesupport
";s:1:"0";s:14:"mimetruncation";s:1:"1";s:8:"conflict";i:1;s:9:"bodyprefs";a:1:{i:1;a:2:{s:4:"type";s:1:"1";s:14:"tru
ncationsize";s:3:"500";}}s:8:"serverid";s:5:"INBOX";s:11:"lastsynckey";s:41:"{51b84b58-a378-4c6e-beb0-202855196ca0}51
9";s:8:"pingable";b:1;}s:10:"@Contacts@";a:11:{s:5:"class";s:8:"Contacts";s:10:"windowsize";s:2:"25";s:10:"filtertype
";s:1:"0";s:10:"truncation";i:0;s:11:"mimesupport";i:0;s:14:"mimetruncation";i:8;s:8:"conflict";i:1;s:9:"bodyprefs";a
:1:{i:1;a:2:{s:4:"type";s:1:"1";s:14:"truncationsize";s:5:"32768";}}s:8:"serverid";s:10:"@Contacts@";s:11:"lastsyncke
y";s:39:"{51b84b59-12c8-4c2a-8edf-202c55196ca0}2";s:8:"pingable";b:1;}s:7:"@Tasks@";a:11:{s:5:"class";s:5:"Tasks";s:1
0:"windowsize";i:100;s:10:"filtertype";s:1:"0";s:10:"truncation";i:0;s:11:"mimesupport";i:0;s:14:"mimetruncation";i:8
;s:8:"conflict";i:1;s:9:"bodyprefs";a:1:{i:1;a:2:{s:4:"type";s:1:"1";s:14:"truncationsize";s:5:"32768";}}s:8:"serveri
d";s:7:"@Tasks@";s:11:"lastsynckey";s:39:"{51b84b5d-cd08-4f77-a435-1ff955196ca0}1";s:8:"pingable";b:1;}}s:13:"pinghea
rtbeat";b:0;s:14:"synckeycounter";a:4:{s:10:"@Calendar@";a:1:{s:39:"{51b84b58-407c-48e4-802c-202c55196ca0}1";i:1;}s:8
:"e69516cf";a:1:{s:41:"{51b84b58-a378-4c6e-beb0-202855196ca0}519";i:0;}s:10:"@Contacts@";a:1:{s:39:"{51b84b59-12c8-4c
2a-8edf-202c55196ca0}1";i:1;}s:7:"@Tasks@";a:1:{i:0;i:1;}}}
2013-06-12T10:48:40+00:00 INFO: [8185] User info@slater.be logged off

Looks like Bug #12339 (for which a fix is available).

i've the same problem after upgrade to Horde 5.1

i can't sync my devices... first initial sync works but then nothing 
is working.
push seems to ge into a loop.
manually sync change nothing...

delete, mark as read, sending emalis works

if i delete all entrys in the active_sync_state table i can do a 
resync and all data is refreshed...

I have installed the latest 2.4.0RC1 and the errors still show up. I 
have reset the activesync devices in Horde but that doesnt help.

Is this still happening with the latest RC1?

The error shows up something between every 3 to every 10 minutes.

I have redirected the activesync log to a custom file but until now 
nothing has shown up there. The server log and the php.error log don´t 
show anything suspicious either.

You definitely shouldn't be seeing this that often unless something is wrong.
Well, normally, yes. But in MS decided in ActiveSync for some reason 
to send this in cases that are errors, but don't necessarily mean 
something is *completely* broken. They typically trigger a resync in 
these cases.
I don't think you should be seeing this that often. Is there anything 
else in the sync log or server log?

I have set error reporting to E_ALL so WARNs should show up. But it´s 
just this error showing up repeatedly every 10 minutes or so with no 
WARN in front of it. I just didn´t think HTTP 500 Errors where 
supposed to happen during normal operations of any system. If it is 
supposed to be like that everything is fine, as I said the sync works 
without noticeable problems otherwise.

There should have been an entry with level WARN above that.

If so, this is just the result of PING not finding any pingable 
collections. For EAS versions < 14 this must return a HTTP 500, hence 
the error message about the 500. It should eventually be followed by a 
either a SYNC or a full PING request.

With Horde_Activesync-2.4.0beta4 this errors startet to show up in the 
horde log althought they do not seem to impair the performance (I use 
activesync with the latest IOS)

2013-05-16T18:05:24+02:00 ERR: HORDE [horde] Returning HTTP 500 while 
handling Ping command. [pid 2408 on line 156 of 
"/var/www/webmail/rpc.php"]
2013-05-16T18:05:24+02:00 ERR: HORDE [horde] Error in communicating 
with ActiveSync server: Received FALSE while handling Ping command. 
[pid 2408 on line 160 of "/usr/share/php/Horde/Rpc/ActiveSync.php"]
2013-05-16T18:05:24+02:00 ERR: HORDE [horde] #0 
/var/www/webmail/rpc.php(156): Horde_Rpc_ActiveSync->getResponse(NULL)
#1 {main} [pid 2408 on line 160 of "/usr/share/php/Horde/Rpc/ActiveSync.php"]
2013-05-16T18:05:24+02:00 ERR: HORDE [horde] Buffer contents:  [pid 
2408 on line 160 of "/usr/share/php/Horde/Rpc/ActiveSync.php"]