6.0.0-git
2019-03-23

[#12506] Contacts sync with ActiveSync get duplicates and not sync
Summary Contacts sync with ActiveSync get duplicates and not sync
Queue Synchronization
Queue Version Git master
Type Bug
State Resolved
Priority 1. Low
Owners mrubinsk (at) horde (dot) org
Requester carlos.velasco (at) nimastelecom (dot) com
Created 2013-07-28 (2064 days ago)
Due
Updated 2013-08-12 (2049 days ago)
Assigned 2013-08-09 (2052 days ago)
Resolved 2013-08-12 (2049 days ago)
Milestone
Patch Yes

History
2013-08-12 19:52:51 Michael Rubinsky Comment #42 Reply to this comment

[Show Quoted Text - 21 lines]
This is because the UI form actually contains those fields. When 
imported, and the fields are not present, the hash does not contain 
those fields and the default for those fields in the DB is null. The 
duplicate detection still works in this case. So, unless you see some 
unwanted behavior because of this, I'll still consider this ticket 
resolved.


2013-08-12 19:36:34 carlos (dot) velasco (at) nimastelecom (dot) com Comment #41 Reply to this comment

[Show Quoted Text - 15 lines]
Well, maybe but if you look directly into database, I see this by example.

When imported from VCard file:
select object_anniversary,object_workemail,object_homeemail from 
turba_objects where object_firstname='TEST';
+--------------------+------------------+------------------+
| object_anniversary | object_workemail | object_homeemail |
+--------------------+------------------+------------------+
| NULL               | NULL             | NULL             |
+--------------------+------------------+------------------+
1 row in set (0.00 sec)

When added manually through Turba web:
select object_anniversary,object_workemail,object_homeemail from 
turba_objects where object_firstname='TESTMANUAL';
+--------------------+------------------+------------------+
| object_anniversary | object_workemail | object_homeemail |
+--------------------+------------------+------------------+
| NULL               |                  |                  |
+--------------------+------------------+------------------+
1 row in set (0.00 sec)

2013-08-12 18:31:51 Michael Rubinsky State ⇒ Resolved
 
2013-08-12 18:30:26 Git Commit Comment #40 Reply to this comment
Changes have been made in Git (master):

commit 07436f188b4e5f7727b176a3192346a943958514
Author: Thomas Jarosch <thomas.jarosch@intra2net.com>
Date:   Fri Aug 9 18:39:02 2013 +0200

     Remove empty 'birthday' or 'anniversary' fields during Kolab 
_store(), otherwise Kolab_Format will try to generate date fields and 
crashes.

     Second part of the fix for bug #12506.

     Signed-off-by: Thomas Jarosch <thomas.jarosch@intra2net.com>
     Signed-off-by: Michael J Rubinsky <mrubinsk@horde.org>

  turba/lib/Driver/Kolab.php |    8 ++++++++
  1 files changed, 8 insertions(+), 0 deletions(-)

http://git.horde.org/horde-git/-/commit/07436f188b4e5f7727b176a3192346a943958514
2013-08-12 17:45:37 Michael Rubinsky Comment #39 Reply to this comment

[Show Quoted Text - 9 lines]
This is the result returned from Turba_Driver::toHash() when I import 
your example:

array(3) { 'homePhone' => string(10) "+555555555" 'firstname' => 
string(4) "TEST" 'name' => string(4) "TEST" }




2013-08-09 16:44:18 Thomas Jarosch Comment #38
State ⇒ Assigned
Patch ⇒ Yes
New Attachment: 0001-Remove-empty-birthday-or-anniversary-fields-during-K.patch Download
Reply to this comment
I've found another place in the Kolab driver that's unhappy if 
'birthday' or 'anniversary' are '' instead of null.

Please apply the attached patch to fix EAS imports.

2013-08-09 10:28:20 carlos (dot) velasco (at) nimastelecom (dot) com Comment #37 Reply to this comment
Note that there are no email fields or so in the imported vcard. Example:
BEGIN:VCARD
VERSION:3.0
TEL;TYPE=HOME,VOICE:+555555555
N:;TEST;;;
FN:TEST
END:VCARD

When imported homeEmail, workEmail and so are set to NULL not to ''

2013-08-09 10:13:46 carlos (dot) velasco (at) nimastelecom (dot) com Comment #36 Reply to this comment
With patch 
http://git.horde.org/horde-git/-/commit/963d725f32fbbe4fb4c5f1b9ff6a9c4a1ab5c235 applied, I still see homeemail and others with NULL after importing a vcard file through turba 
web.

2013-08-08 20:15:27 Michael Rubinsky State ⇒ Resolved
 
2013-08-08 20:12:09 Git Commit Comment #35 Reply to this comment
Changes have been made in Git (master):

commit e766cc017e7f1d5e80487760e189f9529f354cf0
Author: Thomas Jarosch <thomas.jarosch@intra2net.com>
Date:   Thu Aug 8 21:47:30 2013 +0200

     Prevent setting the current date as birthday/anniversary if the 
corresponding field was not given during EAS import

     The bug was "uncovered" by a recent fix for #12506

     Signed-off-by: Thomas Jarosch <thomas.jarosch@intra2net.com>
     Signed-off-by: Michael J Rubinsky <mrubinsk@horde.org>

  turba/lib/Driver/Kolab.php |    4 ++--
  1 files changed, 2 insertions(+), 2 deletions(-)

http://git.horde.org/horde-git/-/commit/e766cc017e7f1d5e80487760e189f9529f354cf0
2013-08-08 20:02:20 Thomas Jarosch Comment #34
State ⇒ Assigned
Reply to this comment
Re-opening so the Kolab patch won't get lost.

2013-08-08 19:50:31 Thomas Jarosch Comment #33
New Attachment: 0001-Prevent-setting-the-current-date-as-birthday-anniver.patch Download
Reply to this comment
Patch to fix the birthday/anniversary field issue with Kolab.

2013-08-08 19:40:36 Michael Rubinsky Comment #32
State ⇒ Resolved
Reply to this comment
Moved remaining issue to Request: 12552 since these are really 
separate issues.
2013-08-08 18:50:56 Git Commit Comment #31 Reply to this comment
Changes have been made in Git (master):

commit 963d725f32fbbe4fb4c5f1b9ff6a9c4a1ab5c235
Author: Michael J Rubinsky <mrubinsk@horde.org>
Date:   Thu Aug 8 14:49:49 2013 -0400

     Ensure the email fields are not set to null Bug: 12506.

  turba/lib/Driver.php |   18 ++++++++++++------
  1 files changed, 12 insertions(+), 6 deletions(-)

http://git.horde.org/horde-git/-/commit/963d725f32fbbe4fb4c5f1b9ff6a9c4a1ab5c235
2013-08-08 18:40:01 Michael Rubinsky Comment #30 Reply to this comment
Hi Mike,

the duplicate detection fix has a nasty side effect:
When you create a new contact on the PIM and don't set a birthday field,
it will set the birthday and anniversary to the current date in turba.
I don't see this. Adding a contact with only a name and address field 
from the client does not set any birthday value for me.
2013-08-08 15:31:52 Michael Rubinsky Comment #29 Reply to this comment
In the patch proposed for the duplicates issue, it works fine for
ActiveSync, but if you import a VCard file (vcf) through Turba wen
interface, these fields are NULL too.
Mike, did you miss this issue?
It seems that import functions let fields at NULL too.
No, the ticket is still open. Not everything is fixed.

2013-08-08 15:13:35 Thomas Jarosch Comment #28 Reply to this comment
Hi Mike,

the duplicate detection fix has a nasty side effect:
When you create a new contact on the PIM and don't set a birthday field,
it will set the birthday and anniversary to the current date in turba.

This is what the client sent on adding a contact:
-----------------------------------
2013-08-08T17:08:01+02:00 DEBUG: [1809] I      <Add>
2013-08-08T17:08:01+02:00 DEBUG: [1809] I       <ClientEntryId>
2013-08-08T17:08:01+02:00 DEBUG: [1809] I         new_39_1375974483846
2013-08-08T17:08:01+02:00 DEBUG: [1809] I       </ClientEntryId>
2013-08-08T17:08:01+02:00 DEBUG: [1809] I       <Data>
2013-08-08T17:08:01+02:00 DEBUG: [1809] I         
<POOMCONTACTS:MobilePhoneNumber>
2013-08-08T17:08:01+02:00 DEBUG: [1809] I          9876/54321
2013-08-08T17:08:01+02:00 DEBUG: [1809] I         
</POOMCONTACTS:MobilePhoneNumber>
2013-08-08T17:08:01+02:00 DEBUG: [1809] I        <POOMCONTACTS:LastName>
2013-08-08T17:08:01+02:00 DEBUG: [1809] I          Koreo
2013-08-08T17:08:01+02:00 DEBUG: [1809] I        </POOMCONTACTS:LastName>
2013-08-08T17:08:01+02:00 DEBUG: [1809] I        <POOMCONTACTS:FirstName>
2013-08-08T17:08:01+02:00 DEBUG: [1809] I          Samsungo
2013-08-08T17:08:01+02:00 DEBUG: [1809] I        </POOMCONTACTS:FirstName>
2013-08-08T17:08:01+02:00 DEBUG: [1809] I        <POOMCONTACTS:FileAs>
2013-08-08T17:08:01+02:00 DEBUG: [1809] I          Samsungo Koreo
2013-08-08T17:08:01+02:00 DEBUG: [1809] I        </POOMCONTACTS:FileAs>
2013-08-08T17:08:01+02:00 DEBUG: [1809] I        <AirSyncBase:Body>
2013-08-08T17:08:01+02:00 DEBUG: [1809] I         <AirSyncBase:Type>
2013-08-08T17:08:01+02:00 DEBUG: [1809] I           1
2013-08-08T17:08:01+02:00 DEBUG: [1809] I         </AirSyncBase:Type>
2013-08-08T17:08:01+02:00 DEBUG: [1809] I         <AirSyncBase:Data>
2013-08-08T17:08:01+02:00 DEBUG: [1809] I
2013-08-08T17:08:01+02:00 DEBUG: [1809] I         </AirSyncBase:Data>
2013-08-08T17:08:01+02:00 DEBUG: [1809] I        </AirSyncBase:Body>
2013-08-08T17:08:01+02:00 DEBUG: [1809] I        <POOMCONTACTS:Email1Address>
2013-08-08T17:08:01+02:00 DEBUG: [1809] I          "Samsungo Koreo" 
<kim@korea.com>
2013-08-08T17:08:01+02:00 DEBUG: [1809] I        </POOMCONTACTS:Email1Address>
2013-08-08T17:08:01+02:00 DEBUG: [1809] I        <POOMCONTACTS:Categories>
2013-08-08T17:08:01+02:00 DEBUG: [1809] I         <POOMCONTACTS:Category>
2013-08-08T17:08:01+02:00 DEBUG: [1809] I           Friends
2013-08-08T17:08:01+02:00 DEBUG: [1809] I         </POOMCONTACTS:Category>
2013-08-08T17:08:01+02:00 DEBUG: [1809] I        </POOMCONTACTS:Categories>
2013-08-08T17:08:01+02:00 DEBUG: [1809] I       </Data>
2013-08-08T17:08:01+02:00 INFO: [1809] 
Horde_Core_ActiveSync_Driver::changeMessage(@Contacts@,  ...)
2013-08-08T17:08:01+02:00 INFO: [1809] Using MODSEQ 2708 for @Contacts@.
2013-08-08T17:08:01+02:00 INFO: [1809] Updating state during change
2013-08-08T17:08:01+02:00 DEBUG: [1809] I      </Add>
-----------------------------------

2013-08-08 14:03:55 carlos (dot) velasco (at) nimastelecom (dot) com Comment #27 Reply to this comment
In the patch proposed for the duplicates issue, it works fine for 
ActiveSync, but if you import a VCard file (vcf) through Turba wen 
interface, these fields are NULL too.
Mike, did you miss this issue?
It seems that import functions let fields at NULL too.

2013-08-07 14:52:11 Michael Rubinsky Comment #26
State ⇒ Assigned
Reply to this comment
Lovely. Since there is no way to determine the number of incoming 
changes until they are all parsed looks like we will still need to 
refactor the client ADD code to not perform the additions until after 
all the data is received instead of the current way of importing them 
as we receive them to save on memory.
2013-08-07 10:02:59 carlos (dot) velasco (at) nimastelecom (dot) com Comment #25
New Attachment: load200.pcapng Download
Reply to this comment
Load 200 contacts with Exchange 2013. Success.

2013-08-07 10:02:22 carlos (dot) velasco (at) nimastelecom (dot) com Comment #24
New Attachment: load250.pcapng Download
Reply to this comment
I managed to test this issue with a Exchange Server 2013.
It "solves" the issue just discarding the Sync returning a Status 4 
for the global sync if the number of contacts is more than 200 
(aprox.) No contacts are added to the account, just a Status 4 is 
returned and the whole sync is discarded.

I am uploading sniffer traces for a load of 200 contacts (success, 
status 1), and a load of 250 contacts (fails, status 4).



2013-08-05 13:28:52 carlos (dot) velasco (at) nimastelecom (dot) com Comment #23 Reply to this comment
In the patch proposed for the duplicates issue, it works fine for 
ActiveSync, but if you import a VCard file (vcf) through Turba wen 
interface, these fields are NULL too.

2013-08-04 18:58:24 carlos (dot) velasco (at) nimastelecom (dot) com Comment #22
New Attachment: android42timeout.pcap Download
Reply to this comment
Tested Android 4.2, using latest sdk: Android/4.2.2-EAS-1.3

It is still worse. The timeout is now as low as 30 seconds.
Uploading pcap sniffer traces with Android 4.2.2

I would like to test this issue with a Exchange Server to see what 
happens and how a Exchange Server handles this, indeed I have access 
to one, but it only uses SSL and I haven't the private RSA key to 
decrypt, it would be really difficult to me.
2013-08-04 17:00:46 Michael Rubinsky Comment #21 Reply to this comment
The issue is that Horde "buffers" the replies and send them all at a 
time later. I have always assumed this is right because you need the 
status for the whole Sync and you can not know this until all 
additions are processed.
This is partially correct. We also need to ensure that the entire 
request is handled before we send any responses and the ADD command 
may not be the only or last command processed. We process the incoming 
data as we receive it so that we don't need to keep all the incoming 
message data in memory before we start processing it.
By examplle If I use the uploaded patch (hack) it only process the 
first 50 ADDs in the packet, this sortens the GAP to less than 1 
minute and workarounds the timeout. With this patch (hack) Android 
seems to work fine and sync all contacts with time.
This patch would completely break synchronization on any EAS client 
that actually follows the specs. It ignores incoming changes and sends 
no status response on those skipped messages. According to the specs 
the client MUST assume the addition worked and should NOT send the 
change(s) again.
What probably should happen is when a duplicate addition is detected
we should return the existing item's UID as if the addition was
successful. Of course, I have no idea what your client will do with
this, since it is demonstrating broken behavior anyway, not to
mention if the connection continues to timeout, this won't help your
original problem anyway.
This sounds really interesting, I would test it, I think it should 
work, there are not additions so the GAP should be low.
Thinking about this some more, I don't think this is the answer 
either. When these sync with the server if we send back the same UID 
for each one of these (an action which is undefined in the EAS spec), 
there could now be multiple copies in the client's datastore that 
connect with the same UID on the backend. What happens when a user 
deletes one of these? Yup, the (only) copy of it on the server is 
deleted. Less worrisome is that there would still be copies of it on 
the client not attached to any server side copy. The state is now 
corrupt. Even if the client doesn't exhibit the broken behavior yours 
does of sending different clientids, it would still be possible for 
the user to add the same contact data accidentally.

If anything is to be done here to mitigate this, I think we need to 
totally rewrite the way incoming changes are handled so that we don't 
actually process them until they are all read. We will use more memory 
on the incoming request but we will be able to start sending packets 
back to the client more quickly.  I'm not sure I like this, as one of 
the things that differentiates Horde's activesync implementation is 
relatively low memory consumption per request and I have not been able 
to find any protocol related documentation as to any incoming change 
time limits. I think the use case of importing hundreds and hundreds 
of new contacts FROM THE CLIENT is relatively rare.
2013-08-04 12:01:22 carlos (dot) velasco (at) nimastelecom (dot) com Comment #20
New Attachment: horde-eas-synchack-1.patch Download
Reply to this comment
Well, from what you told me earlier, your device is not receiving 
*any* response from the server before it closes the connection. It 
doesn't matter what response we send if the client never sees it.
Not exactly, the problem is the timeout (gap) between input from 
device and output from horde.

This is:
Device: Begin sending contacts
Device : Finish ADD contacts, waiting reply
GAP: Horde Begin adding contacts.
GAP: Horde Finish adding cotacts.
Horde: Begins sending replies (status).
...

If the GAP time is above 80 seconds (aprox.) Android timeouts and 
close the connection *before* Horde begins sending replies. I have 
tested other Android devices and this seems the behaviour in all 
Android 4.1 versions. I need to test with 4.2 to see how this behave.

The issue is that Horde "buffers" the replies and send them all at a 
time later. I have always assumed this is right because you need the 
status for the whole Sync and you can not know this until all 
additions are processed. So I think in this process time the timeout 
occurs because device does not receive any packet from Horde.

If we reduce the process time, we reduce the "GAP" so this problem 
does not arise.

By examplle If I use the uploaded patch (hack) it only process the 
first 50 ADDs in the packet, this sortens the GAP to less than 1 
minute and workarounds the timeout. With this patch (hack) Android 
seems to work fine and sync all contacts with time.
What probably should happen is when a duplicate addition is detected 
we should return the existing item's UID as if the addition was 
successful. Of course, I have no idea what your client will do with 
this, since it is demonstrating broken behavior anyway, not to 
mention if the connection continues to timeout, this won't help your 
original problem anyway.
This sounds really interesting, I would test it, I think it should 
work, there are not additions so the GAP should be low.

2013-08-03 15:59:44 Michael Rubinsky Comment #19 Reply to this comment
Later, as the client device does not see any reply for these entries 
it tries to upload them again and again and again... dups detected, 
of course, but this is bad.
Well, from what you told me earlier, your device is not receiving 
*any* response from the server before it closes the connection. It 
doesn't matter what response we send if the client never sees it.
Looking at EAS docs maybe a Status 7 should be replied?
http://msdn.microsoft.com/en-us/library/gg675457%28v=exchg.80%29.aspx
===
7
No, STATUS_CONFLICT is only to be used with an item successfully 
synced by the client (the client knows the item's server-side UID)   
that has changed on both the client and server.

What probably should happen is when a duplicate addition is detected 
we should return the existing item's UID as if the addition was 
successful. Of course, I have no idea what your client will do with 
this, since it is demonstrating broken behavior anyway, not to mention 
if the connection continues to timeout, this won't help your original 
problem anyway. As I said before uploading hundreds of new messages 
from the client to the server is NOT something the protocol was 
originally designed to handle.
On the other hand, it seems interesting that if the Android device 
doesn't see any status reply for some items it behaves like if they 
were not accepted by the server and try again.
No, in fact it's the exact opposite (though I agree the spec doesn't 
make much sense here). From MS-ASCMD 2.2.3.7:

==
The server is not required to send an individual response for every 
operation that is sent by the client. The client only receives 
responses for successful additions and fetches, and failed changes and 
deletions. When the client does not receive a response, the client 
MUST assume that the operation succeeded unless informed otherwise.
==

So, no, the client should NOT resend an item if it does not receive 
ANY status response. Of course, for client -> server additions the 
behavior of any further actions would be undetermined since the client 
would not know the server's UID. Rather, from what you told me 
earlier, your client is resending the messages because it did not 
receive ANY response before the connection was closed.
Maybe this could be used for pacing the client uploads.
No. As stated earlier, there is no paging of the client uploads in the 
EAS protocol. Attempting to abuse some status code that should have 
another meaning is nothing more that a hack to get around broken 
client behavior.


2013-08-03 11:22:03 carlos (dot) velasco (at) nimastelecom (dot) com Comment #18 Reply to this comment
Tested the patch and it works, it detects duplicates now.
2013-08-03T13:07:54+02:00 INFO: [15950] 
Horde_Core_ActiveSync_Driver::changeMessage(@Contacts@,  ...)
2013-08-03T13:07:54+02:00 ERR: Already Exists

However, when this happens the server doesn't reply anything for these 
entries, no status is replied for them to client (Android).

Later, as the client device does not see any reply for these entries 
it tries to upload them again and again and again... dups detected, of 
course, but this is bad.

Looking at EAS docs maybe a Status 7 should be replied?
http://msdn.microsoft.com/en-us/library/gg675457%28v=exchg.80%29.aspx
===
7
Conflict matching the client and server object.
The client has changed an item for which the conflict policy indicates 
that the server's changes take precedence.
Item
If it is necessary, inform the user that the change they made to the 
item has been overwritten by a server change.
===

On the other hand, it seems interesting that if the Android device 
doesn't see any status reply for some items it behaves like if they 
were not accepted by the server and try again. Maybe this could be 
used for pacing the client uploads.

2013-08-02 18:00:43 Michael Rubinsky Comment #17
Assigned to Michael Rubinsky
State ⇒ Resolved
Reply to this comment
Marking as resolved since the Turba duplicate detection will now 
prevent the duplicates from being added.

Still won't solve the timeout issue on the device, but there is 
nothing Horde can do about that.
2013-08-02 17:58:10 Michael Rubinsky Comment #16 Reply to this comment
On the other hand, I don't really understand the query.
If matching is done with wildcards, two contacts like "Carlo" and 
"Carlota" would match and could be considerated dups, when they are 
not.
*All* the fields must match the query, so unless Carlo and Carlota 
have entries in all the fields that would match in the same way, they 
will not be detected as dups.
2013-08-02 17:52:21 Git Commit Comment #15 Reply to this comment
Changes have been made in Git (master):

commit f52676bd1cc63ab80423038970628aa9f8321508
Author: Michael J Rubinsky <mrubinsk@horde.org>
Date:   Fri Aug 2 13:49:41 2013 -0400

     Add test for Bug: 12506

  turba/test/Turba/Unit/Driver/Base.php |   13 +++++++++++++
  1 files changed, 13 insertions(+), 0 deletions(-)

http://git.horde.org/horde-git/-/commit/f52676bd1cc63ab80423038970628aa9f8321508
2013-08-02 17:52:17 Git Commit Comment #14 Reply to this comment
Changes have been made in Git (master):

commit 96886eea55280554292e2dcddf19cee288e314bd
Author: Michael J Rubinsky <mrubinsk@horde.org>
Date:   Fri Aug 2 13:48:49 2013 -0400

     Bug: 12506  Fix detecting duplicate additions from EAS contacts 
with no email addresses.

  turba/lib/Driver.php |   20 ++++++++++++--------
  1 files changed, 12 insertions(+), 8 deletions(-)

http://git.horde.org/horde-git/-/commit/96886eea55280554292e2dcddf19cee288e314bd
2013-07-30 18:02:53 carlos (dot) velasco (at) nimastelecom (dot) com Comment #13 Reply to this comment
On the other hand, I don't really understand the query.
If matching is done with wildcards, two contacts like "Carlo" and 
"Carlota" would match and could be considerated dups, when they are not.
Why the wildcards there?

2013-07-30 17:49:32 carlos (dot) velasco (at) nimastelecom (dot) com Comment #12 Reply to this comment
This could be because the client is receiving *some* of the 
responses before timing out, but if it decides the sync is 
unsuccessful, it should not regenerate those ids.
No, don't think so, Android is closing TCP connection before receiving 
anything from Horde.
What I don't understand yet though is why Turba is letting the 
duplicates be added. There is code in Turba_Api::import() that is 
supposed to reject entries that contain the exact same data (current 
Git - Turba/lib/Api.php line 745. You can add some debug logging 
there and compare the value of $content for each attempt.
Well, this is weird.

The $content is something like this:
array(61) {
   ["name"]=>
   string(6) "foo496"
   ["lastname"]=>
   string(0) ""
   ["firstname"]=>
   string(6) "foo496"
   ["middlenames"]=>
   string(0) ""
   ["alias"]=>
   string(0) ""
   ["nickname"]=>
   string(0) ""
   ["namePrefix"]=>
   string(0) ""
   ["nameSuffix"]=>
   string(0) ""
   ["homeStreet"]=>
   string(0) ""
   ["homeCity"]=>
   string(0) ""
   ["homeProvince"]=>
   string(0) ""
   ["homePostalCode"]=>
   string(0) ""
   ["homeCountryFree"]=>
   string(0) ""
   ["otherStreet"]=>
   string(0) ""
   ["otherCity"]=>
   string(0) ""
   ["otherProvince"]=>
   string(0) ""
   ["otherPostalCode"]=>
   string(0) ""
   ["otherCountryFree"]=>
   string(0) ""
   ["workStreet"]=>
   string(0) ""
   ["workCity"]=>
   string(0) ""
   ["workProvince"]=>
   string(0) ""
   ["workPostalCode"]=>
   string(0) ""
   ["workCountryFree"]=>
   string(0) ""
   ["title"]=>
   string(0) ""
   ["company"]=>
   string(0) ""
   ["department"]=>
   string(0) ""
   ["office"]=>
   string(0) ""
   ["spouse"]=>
   string(0) ""
   ["website"]=>
   string(0) ""
   ["assistant"]=>
   string(0) ""
   ["manager"]=>
   string(0) ""
   ["yomifirstname"]=>
   string(0) ""
   ["yomilastname"]=>
   string(0) ""
   ["imaddress"]=>
   string(0) ""
   ["imaddress2"]=>
   string(0) ""
   ["imaddress3"]=>
   string(0) ""
   ["homePhone"]=>
   string(11) "+3466666496"
   ["homePhone2"]=>
   string(0) ""
   ["workPhone"]=>
   string(0) ""
   ["workPhone2"]=>
   string(0) ""
   ["fax"]=>
   string(0) ""
   ["homeFax"]=>
   string(0) ""
   ["pager"]=>
   string(0) ""
   ["cellPhone"]=>
   string(0) ""
   ["carPhone"]=>
   string(0) ""
   ["assistPhone"]=>
   string(0) ""
   ["companyPhone"]=>
   string(0) ""
   ["radioPhone"]=>
   string(0) ""
   ["notes"]=>
   string(0) ""
   ["photo"]=>
   string(0) ""
   ["emails"]=>
   string(2) ",,"
   ["email"]=>
   NULL
   ["homeEmail"]=>
   NULL
   ["workEmail"]=>
   NULL
   ["category"]=>
   string(0) ""
   ["children"]=>
   string(0) ""
   ["birthday"]=>
   NULL
   ["anniversary"]=>
   NULL
   ["homeCountry"]=>
   NULL
   ["workCountry"]=>
   NULL
   ["otherCountry"]=>
   NULL
}

But the search returns 0. Why?

The complete SQL is:
         SELECT object_id, owner_id, object_type, object_members, object_uid,
           object_firstname, object_lastname, object_middlenames,
           object_nameprefix, object_namesuffix, object_alias,
           object_yomifirstname, object_yomilastname, object_bday,
           object_anniversary, object_spouse, object_photo, object_phototype,
           object_homestreet, object_homepob, object_homecity,
           object_homeprovince, object_homepostalcode, object_homecountry,
           object_workstreet, object_workpob, object_workcity,
           object_workprovince, object_workpostalcode, object_workcountry,
           object_otherstreet, object_otherpob, object_othercity,
           object_otherprovince, object_otherpostalcode, object_othercountry,
           object_department, object_manager, object_assistant, object_tz,
           object_homeemail, object_homephone, object_homephone2, 
object_homefax,
           object_workphone, object_workphone2, object_cellphone,
           object_carphone, object_radiophone, object_companyphone,
           object_assistantphone, object_fax, object_pager, object_title,
           object_role, object_company, object_logo, object_logotype,
           object_category, object_notes, object_url, object_freebusyurl,
           object_pgppublickey, object_smimepublickey, object_imaddress,
           object_imaddress2, object_imaddress3, object_workemail FROM
           turba_objects WHERE (owner_id = 'testas@nimastelecom.com' AND
           ((LOWER(object_nameprefix) LIKE LOWER('%foo73%') OR
           LOWER(object_firstname) LIKE LOWER('%foo73%') OR
           LOWER(object_middlenames) LIKE LOWER('%foo73%') OR
           LOWER(object_lastname) LIKE LOWER('%foo73%') OR
           LOWER(object_namesuffix) LIKE LOWER('%foo73%')) AND
           LOWER(object_lastname) LIKE LOWER('%%') AND LOWER(object_firstname)
           LIKE LOWER('%foo73%') AND LOWER(object_middlenames) LIKE LOWER('%%')
           AND LOWER(object_alias) LIKE LOWER('%%') AND 
LOWER(object_nameprefix)
           LIKE LOWER('%%') AND LOWER(object_namesuffix) LIKE LOWER('%%') AND
           LOWER(object_homestreet) LIKE LOWER('%%') AND LOWER(object_homecity)
           LIKE LOWER('%%') AND LOWER(object_homeprovince) LIKE LOWER('%%') AND
           LOWER(object_homepostalcode) LIKE LOWER('%%') AND
           LOWER(object_otherstreet) LIKE LOWER('%%') AND 
LOWER(object_othercity)
           LIKE LOWER('%%') AND LOWER(object_otherprovince) LIKE 
LOWER('%%') AND
           LOWER(object_otherpostalcode) LIKE LOWER('%%') AND
           LOWER(object_workstreet) LIKE LOWER('%%') AND LOWER(object_workcity)
           LIKE LOWER('%%') AND LOWER(object_workprovince) LIKE LOWER('%%') AND
           LOWER(object_workpostalcode) LIKE LOWER('%%') AND 
LOWER(object_title)
           LIKE LOWER('%%') AND LOWER(object_company) LIKE LOWER('%%') AND
           LOWER(object_department) LIKE LOWER('%%') AND LOWER(object_spouse)
           LIKE LOWER('%%') AND LOWER(object_url) LIKE LOWER('%%') AND
           LOWER(object_assistant) LIKE LOWER('%%') AND LOWER(object_manager)
           LIKE LOWER('%%') AND LOWER(object_yomifirstname) LIKE 
LOWER('%%') AND
           LOWER(object_yomilastname) LIKE LOWER('%%') AND
           LOWER(object_imaddress) LIKE LOWER('%%') AND 
LOWER(object_imaddress2)
           LIKE LOWER('%%') AND LOWER(object_imaddress3) LIKE LOWER('%%') AND
           LOWER(object_homephone) LIKE LOWER('%+346666673%') AND
           LOWER(object_homephone2) LIKE LOWER('%%') AND 
LOWER(object_workphone)
           LIKE LOWER('%%') AND LOWER(object_workphone2) LIKE LOWER('%%') AND
           LOWER(object_fax) LIKE LOWER('%%') AND LOWER(object_homefax) LIKE
           LOWER('%%') AND LOWER(object_pager) LIKE LOWER('%%') AND
           LOWER(object_cellphone) LIKE LOWER('%%') AND LOWER(object_carphone)
           LIKE LOWER('%%') AND LOWER(object_assistantphone) LIKE 
LOWER('%%') AND
           LOWER(object_companyphone) LIKE LOWER('%%') AND
           LOWER(object_radiophone) LIKE LOWER('%%') AND 
LOWER(object_notes) LIKE
           LOWER('%%') AND LOWER(object_homeemail) LIKE LOWER('%%') AND
           LOWER(object_homeemail) LIKE LOWER('%%') AND LOWER(object_workemail)
           LIKE LOWER('%%') AND LOWER(object_category) LIKE LOWER('%%') AND
           LOWER(object_bday) LIKE LOWER('%%') AND 
LOWER(object_anniversary) LIKE
           LOWER('%%') AND LOWER(object_homecountry) LIKE LOWER('%%') AND
           LOWER(object_workcountry) LIKE LOWER('%%') AND
           LOWER(object_othercountry) LIKE LOWER('%%')));


Returns 0 because in the "LOWER(object_homeemail) LIKE LOWER('%%')", 
this field is NULL in these contacts and NULL does not match in LIKE 
wildcards.
Same for object_workemail.

These fields are mapped in my backend local.
$cfgSources['localsql']['map']['email'] = 'object_homeemail';
$cfgSources['localsql']['map']['homeEmail'] = 'object_homeemail';
$cfgSources['localsql']['map']['workEmail'] = 'object_workemail';

And are as type email in attributes.

2013-07-29 23:22:25 Michael Rubinsky Comment #11 Reply to this comment
I think that something should be used to limit this problem somehow, 
blocking android device if we detect this problem or something. 
Don't know how.
We already attempt to detect duplicate additions from the client by 
using the only bit of uniquely identifying data the client provides 
with new entries - the ClientEntryId value. The client is supposed to 
save this value until it receives a response from the server mapping a 
server UID with the ClientEntryId. The problem in your case is that 
your client is sending a *different* value for this field with each 
attempt. This could be because the client is receiving *some* of the 
responses before timing out, but if it decides the sync is 
unsuccessful, it should not regenerate those ids.

What I don't understand yet though is why Turba is letting the 
duplicates be added. There is code in Turba_Api::import() that is 
supposed to reject entries that contain the exact same data (current 
Git - Turba/lib/Api.php line 745. You can add some debug logging there 
and compare the value of $content for each attempt.
2. About the real timeout issue, I was thinking about limiting and 
accepting just 20 entries from the phone at a time.
I am not an ActiveSync expert, should this work or you must accept 
the full sync?
This is what I meant when I said that there is no mechanism in place 
to page incoming changes. All incoming requests must be handled, or an 
explicit error code for the failure must be sent...and there is no 
error code for "Too many messages sent". Simply ignoring the other 
entries will cause the device to believe that they have been 
successfully added when in fact they have not. This is per the EAS 
specs. The reverse is not true - the client will only request a subset 
of all server changes at a time.
2013-07-29 22:11:48 carlos (dot) velasco (at) nimastelecom (dot) com Comment #10 Reply to this comment

[Show Quoted Text - 10 lines]
Well, I see 2 issues here:

1.  With this timeout issue Android device thinks that contacts are 
not uploaded and then tries to upload contacts again and again.
Just 1 android device managed to turn down my mysql in some hours with 
hundreds of dups...
It is a real problem if we think that admins (we) can't control what 
users do with their devices and this issue is rather trivial.
I think that something should be used to limit this problem somehow, 
blocking android device if we detect this problem or something. Don't 
know how.

2. About the real timeout issue, I was thinking about limiting and 
accepting just 20 entries from the phone at a time.
I am not an ActiveSync expert, should this work or you must accept the 
full sync?
I was looking into Horde Activesync code to do this but I am a total 
newbie here.

2013-07-29 21:47:36 Michael Rubinsky Comment #9
State ⇒ Not A Bug
Priority ⇒ 1. Low
Reply to this comment
Definitely this seems a timeout issue.

I have taken sniffer traces of the 500 contacts upload.
After waiting 80 seconds for answer from server (Horde), it sends a 
FIN packet, connection is closed in Android side.
Then there is really nothing Horde can do about this. We don't have 
any control over when Android is going to decide it's taking too long. 
As mentioned below, you should import this many contacts on the Turba 
side first.

2013-07-29 21:45:44 Michael Rubinsky Comment #8 Reply to this comment
So, it seems that in the 500 contacts log, after the initial upload 
of the 500 contacts from Android to Turba, the Android SyncKey is 
not updated from {51f5844b-ef0c-4b3a-937b-784b5570088c}2 to 
{51f5844b-ef0c-4b3a-937b-784b5570088c}3.
Ah, you are importing the new contacts from the device. I missed that.

The protocol is not really optimized/designed for importing that many 
new items from the device to the server. It was originally designed to 
be a mirror of an already existing Exchange account. As such, there is 
no mechanism in place in the protocol to "page" changes from client -> 
server as there is in the other direction.

E.g., if you were to import the 500 new contacts into Turba the 
changes would be sent to the client in multiple requests, each 
containing a small chunk of the changes (the exact number is client 
dependent but usually ranges from 5 - 20).

2013-07-29 21:39:01 Michael Rubinsky Comment #7 Reply to this comment
This entry in debug log sounds bad:
2013-07-28T23:01:52+02:00 NOTICE: [30665] Error saving state for 
synckey {51f5844b-ef0c-4b3a-937b-784b5570088c}3: QUERY FAILED: 
Duplicate entry '{51f5844b-ef0c-4b3a-937b-784b5570088c}3' for key 
'PRIMARY'
No, not bad. It's a NOTICE that means the device sent the same request 
to Horde multiple times. It's an indicator that the device either did 
not receive the entire response to the most recent request or it did 
not accept the response for some reason.
2013-07-29 21:37:37 Michael Rubinsky Comment #6 Reply to this comment
Sync contacts with Turba and Android fails and generates duplicates 
in Horde 5.1.2 Turba 4.1.1

Client Device: Samsung Galaxy S2 i9100 Android ICS 4.1.2

In my tests I have generated a test.vcf file with 500 contacts 
("foo1"-"foo500").
Attaching the ActiveSync debug log.
Your log file shows the DEVICE sending incoming contacts to Horde not 
Horde sending contacts to the device. Then there are a whole bunch of 
<REMOVE> commands sent to the device from horde.  You should clear 
your device completely, i.e., delete and recreate the activesync 
account before testing this again.
2013-07-29 11:52:16 carlos (dot) velasco (at) nimastelecom (dot) com Comment #5
New Attachment: capttimeout.pcap Download
Reply to this comment
Definitely this seems a timeout issue.

I have taken sniffer traces of the 500 contacts upload.
After waiting 80 seconds for answer from server (Horde), it sends a 
FIN packet, connection is closed in Android side.

Uploading sniffer traces of these packets.

2013-07-29 11:03:44 carlos (dot) velasco (at) nimastelecom (dot) com Comment #4
New Attachment: new2.txt Download
Reply to this comment
I made another test with just 5 contacts and it works, so this issue 
seems related to volume contacts. Attaching new debug logs with 5 
contacts.

Looking into both logs I see this:

In the 500 contacts log:
2013-07-28T22:54:05+02:00 DEBUG: [30637] I     <SyncKey>
2013-07-28T22:54:05+02:00 DEBUG: [30637] I       
{51f5844b-ef0c-4b3a-937b-784b5570088c}2
2013-07-28T22:54:05+02:00 DEBUG: [30637] I     </SyncKey>
...
2013-07-28T22:59:01+02:00 DEBUG: [30637] I  </Synchronize>
...
2013-07-28T22:59:10+02:00 DEBUG: [30637] O     <SyncKey>
2013-07-28T22:59:10+02:00 DEBUG: [30637] O       
{51f5844b-ef0c-4b3a-937b-784b5570088c}3
2013-07-28T22:59:10+02:00 DEBUG: [30637] O     </SyncKey>
...
2013-07-28T23:01:36+02:00 DEBUG: [30665] SYNC request received for 
user testas@nimastelecom.com
...
2013-07-28T23:01:37+02:00 DEBUG: [30665] I    <Folder>
2013-07-28T23:01:37+02:00 DEBUG: [30665] I     <SyncKey>
2013-07-28T23:01:37+02:00 DEBUG: [30665] I       
{51f5844b-ef0c-4b3a-937b-784b5570088c}2
2013-07-28T23:01:37+02:00 DEBUG: [30665] I     </SyncKey>
2013-07-28T23:01:37+02:00 DEBUG: [30665] I     <FolderId>
2013-07-28T23:01:37+02:00 DEBUG: [30665] I       @Contacts@
2013-07-28T23:01:37+02:00 DEBUG: [30665] I     </FolderId>
2013-07-28T23:01:37+02:00 DEBUG: [30665] I     <DeletesAsMoves />
2013-07-28T23:01:37+02:00 DEBUG: [30665] I     <GetChanges />
2013-07-28T23:01:37+02:00 DEBUG: [30665] I     <WindowSize>
2013-07-28T23:01:37+02:00 DEBUG: [30665] I       5
2013-07-28T23:01:37+02:00 DEBUG: [30665] I     </WindowSize>
2013-07-28T23:01:37+02:00 DEBUG: [30665] I     <Options>
2013-07-28T23:01:37+02:00 DEBUG: [30665] I      <AirSyncBase:BodyPreference>
2013-07-28T23:01:37+02:00 DEBUG: [30665] I       <AirSyncBase:Type>
2013-07-28T23:01:37+02:00 DEBUG: [30665] I         1
2013-07-28T23:01:37+02:00 DEBUG: [30665] I       </AirSyncBase:Type>
2013-07-28T23:01:37+02:00 DEBUG: [30665] I       <AirSyncBase:TruncationSize>
2013-07-28T23:01:37+02:00 DEBUG: [30665] I         400000
2013-07-28T23:01:37+02:00 DEBUG: [30665] I       </AirSyncBase:TruncationSize>
2013-07-28T23:01:37+02:00 DEBUG: [30665] I      </AirSyncBase:BodyPreference>
2013-07-28T23:01:37+02:00 DEBUG: [30665] I     </Options>
2013-07-28T23:01:37+02:00 DEBUG: [30665] I    </Folder>

In the 5 contacts log:
2013-07-29T12:20:07+02:00 DEBUG: [8841] I     <SyncKey>
2013-07-29T12:20:07+02:00 DEBUG: [8841] I       
{51f64171-3fc0-4f87-ba3b-22a55570088c}2
2013-07-29T12:20:07+02:00 DEBUG: [8841] I     </SyncKey>
...
2013-07-29T12:20:11+02:00 DEBUG: [8841] I  </Synchronize>
...
2013-07-29T12:20:12+02:00 DEBUG: [8841] O     <SyncKey>
2013-07-29T12:20:12+02:00 DEBUG: [8841] O       
{51f64171-3fc0-4f87-ba3b-22a55570088c}3
2013-07-29T12:20:12+02:00 DEBUG: [8841] O     </SyncKey>
...
2013-07-29T12:20:13+02:00 DEBUG: [8841] SYNC request received for user 
testas@nimastelecom.com
...
2013-07-29T12:20:13+02:00 DEBUG: [8841] I    <Folder>
2013-07-29T12:20:13+02:00 DEBUG: [8841] I     <SyncKey>
2013-07-29T12:20:13+02:00 DEBUG: [8841] I       
{51f64171-3fc0-4f87-ba3b-22a55570088c}3
2013-07-29T12:20:13+02:00 DEBUG: [8841] I     </SyncKey>
2013-07-29T12:20:13+02:00 DEBUG: [8841] I     <FolderId>
2013-07-29T12:20:13+02:00 DEBUG: [8841] I       @Contacts@
2013-07-29T12:20:13+02:00 DEBUG: [8841] I     </FolderId>
2013-07-29T12:20:13+02:00 DEBUG: [8841] I     <DeletesAsMoves />
2013-07-29T12:20:13+02:00 DEBUG: [8841] I     <GetChanges />
2013-07-29T12:20:13+02:00 DEBUG: [8841] I     <WindowSize>
2013-07-29T12:20:13+02:00 DEBUG: [8841] I       5
2013-07-29T12:20:13+02:00 DEBUG: [8841] I     </WindowSize>
2013-07-29T12:20:13+02:00 DEBUG: [8841] I     <Options>
2013-07-29T12:20:13+02:00 DEBUG: [8841] I      <AirSyncBase:BodyPreference>
2013-07-29T12:20:13+02:00 DEBUG: [8841] I       <AirSyncBase:Type>
2013-07-29T12:20:13+02:00 DEBUG: [8841] I         1
2013-07-29T12:20:13+02:00 DEBUG: [8841] I       </AirSyncBase:Type>
2013-07-29T12:20:13+02:00 DEBUG: [8841] I       <AirSyncBase:TruncationSize>
2013-07-29T12:20:13+02:00 DEBUG: [8841] I         400000
2013-07-29T12:20:13+02:00 DEBUG: [8841] I       </AirSyncBase:TruncationSize>
2013-07-29T12:20:13+02:00 DEBUG: [8841] I      </AirSyncBase:BodyPreference>
2013-07-29T12:20:13+02:00 DEBUG: [8841] I     </Options>
2013-07-29T12:20:13+02:00 DEBUG: [8841] I    </Folder>

So, it seems that in the 500 contacts log, after the initial upload of 
the 500 contacts from Android to Turba, the Android SyncKey is not 
updated from {51f5844b-ef0c-4b3a-937b-784b5570088c}2 to 
{51f5844b-ef0c-4b3a-937b-784b5570088c}3.

However in the 5 contacts log, the synckey in Android gets updated 
without problem.

Maybe some timeout issue??
In the 500 contacts case it gets more than 5 minutes to upload for 5 
seconds in the 5 contacts case.

I am trying to activate debug logs in Android client, but not sure how 
to do it.

In the other hand, Horde/Turba should handle this problem somehow. 
Right now it generates an error because backend is mysql and little 
more. It seems that Android device tries to upload and upload and 
upload the contacts again and again after some time leading to 
thousand of duplicated contacts in Turba.

2013-07-29 00:43:05 carlos (dot) velasco (at) nimastelecom (dot) com Comment #3 Reply to this comment
This entry in debug log sounds bad:
2013-07-28T23:01:52+02:00 NOTICE: [30665] Error saving state for 
synckey {51f5844b-ef0c-4b3a-937b-784b5570088c}3: QUERY FAILED: 
Duplicate entry '{51f5844b-ef0c-4b3a-937b-784b5570088c}3' for key 
'PRIMARY'

2013-07-28 21:48:43 carlos (dot) velasco (at) nimastelecom (dot) com Comment #2
New Attachment: test.vcf Download
Reply to this comment
The test.vcf file used in my test

2013-07-28 21:47:20 carlos (dot) velasco (at) nimastelecom (dot) com Comment #1
Type ⇒ Bug
State ⇒ Unconfirmed
Priority ⇒ 2. Medium
Summary ⇒ Contacts sync with ActiveSync get duplicates and not sync
Queue ⇒ Synchronization
Milestone ⇒
Patch ⇒ No
New Attachment: SAMSUNG1359090042570562.zip Download
Reply to this comment
Sync contacts with Turba and Android fails and generates duplicates in 
Horde 5.1.2 Turba 4.1.1

Client Device: Samsung Galaxy S2 i9100 Android ICS 4.1.2

In my tests I have generated a test.vcf file with 500 contacts 
("foo1"-"foo500").
Attaching the ActiveSync debug log.

Steps:
1. Sync the device with empty contacts with Horde.
2. Import vcf file in device in ActiveSync account. -> Around 
2013-07-28T22:53:33+02:00 in the debug log.
3. Device is synced (upload contact to Horde is ok).
4.  Through Turba (web) I deleted contacts "foo102"-"foo105". -> 
Around  2013-07-28T23:01:17+02:00 in the debug log.
5. Device is not synced, contacs still appears in the device.
6. Device start "sync now". -> Around 2013-07-28T23:04:47+02:00 in the 
debug log.
7. All contacts get duplicated in Turba. All contacts appears twice 
but the deleted ones that only have 1 entry each.
     Contacts in device are NOT duplicated, all contacts appears in 
the device, including the deleted ones.

Saved Queries