SlowSync with Nokia N73

Hi everybody,

I'm trying desperately getting SyncML to work with a N73.
Actually it
worked pretty fine for a while, but since a week or so i am
always
getting slow syncs, resulting in duplicate calendar
entries,
especially when they are repeating (e.g. birthdays).

I'm just using contacts-synchronisation for the sake of
simplicity right now,
using the latest CVS version from this morning, php error
log shows no errors.

I truncated the horde_syncml_map table and deleted all
syncml-data in
the setup prior to the following:

the first (slow-sync) works fine, the second sync is a fast
sync; the
log shows that the timestamps match. starting with the third
sync i
only get slow syncs because the timestamps don't match. See
the
attached syncml_log.txt extracts:

initial first sync (with empty syncml_map-table):

DEBUG:  Backend of class SyncML_Backend_Horde created
DEBUG:  New session created:
82a530bb786584c894fb8fd6f13b6d2f
DEBUG:  checking auth for user=userdomain.de
DEBUG:  authorized=1 version=2 msgid=1
source=IMEI:3536400XXXXXXXX target=https:
//portal.domain.de:443/rpc.php user=userdomain.de
charset
=UTF-8 wbxml=1
DEBUG:  SyncML: No info about previous syncs found for
device
IMEI:3536400XXXXXXXX and database ./contacts
DEBUG:  Create new sync for ./contacts; synctype=201
DEBUG:  HandleFinal for state=0
DEBUG:  Received Final from client.
DEBUG:  Sending Final to client.
DEBUG:  SyncML: return message completed
DEBUG:  Finished at 2007-03-19 14:53:04. Packet logged in
/tmp/sync/syncml_server_10.wbxml

DEBUG:  Backend of class SyncML_Backend_Horde created
DEBUG:  Existing session continued:
82a530bb786584c894fb8fd6f13b6d2f
DEBUG:  authorized=1 version=2 msgid=2
source=IMEI:3536400XXXXXXXX target=https:
//portal.domain.de:443/rpc.php user=userdomain.de
charset
=UTF-8 wbxml=1
DEBUG:  created device class SyncML_Device_Nokia
DEBUG:  Handling client sent Add
DEBUG:  Add: Already exists with
uid=20070319122056.6n75qwqx400oportal.domain.de
DEBUG:  added client entry as
20070319122056.6n75qwqx400oportal.domain.d
e
DEBUG:  Handling client sent Add
DEBUG:  Add: Already exists with
suid=20070319122056.6uo564p393q0portal.domain.de
DEBUG:  added client entry as
20070319122056.6uo564p393q0portal.domain.d
e
[...]
DEBUG:  HandleFinal for state=1
DEBUG:  server create sync output for syncType=./contacts
DEBUG:  Compiling server changes from 1970-01-01 01:00:00 to
2007-03-19 14:53:04
DEBUG:  slowsync-add: 20070319122056.6n75qwqx400oportal.domain.de ignored
DEBUG:  slowsync-add: 20070319122056.6uo564p393q0portal.domain.de ignored
[...]
DEBUG:  sending 0 server changes for syncType=./contacts
DEBUG:  Received Final from client.
DEBUG:  Sending Final to client.
DEBUG:  SyncML: return message completed
DEBUG:  Finished at 2007-03-19 14:53:31. Packet logged in
/tmp/sync/syncml_server_18.wbxml

DEBUG:  Backend of class SyncML_Backend_Horde created
DEBUG:  Existing session continued:
82a530bb786584c894fb8fd6f13b6d2f
DEBUG:  authorized=1 version=2 msgid=10
source=IMEI:3536400XXXXXXXX
target=https://portal.d
omain.de:443/rpc.php user=userdomain.de
charset=UTF-8 wbxml=1
DEBUG:  HandleFinal for state=3
DEBUG:  Received Final from client.
DEBUG:  Sending Final to client.
INFO:   Successful sync of ./contacts! Summary: failures=0;
client(Add,Replace,Delete,AddReplaces)=176,0,0,0;
server(Add,Replac
e,Delete)=0,0,0
DEBUG:  Finished at 2007-03-19 14:53:32. Packet logged in
/tmp/sync/syncml_server_19.wbxml


this is the second (successful) sync:

DEBUG:  Backend of class SyncML_Backend_Horde created
DEBUG:  New session created:
519bb700184ca0bc7b32ae44cdd4774e
DEBUG:  checking auth for user=userdomain.de
DEBUG:  authorized=1 version=2 msgid=1
source=IMEI:3536400XXXXXXXX
target=https://portal.d
omain.de:443/rpc.php user=userdomain.de
charset=UTF-8 wbxml=1
DEBUG:  previous sync found for database: ./contacts;
client-ts:
20070319T145033Z
DEBUG:  SyncML: Anchor match, TwoWaySync since
20070319T145033Z
DEBUG:  Create new sync for ./contacts; synctype=200
DEBUG:  HandleFinal for state=0
DEBUG:  Received Final from client.
DEBUG:  Sending Final to client.
DEBUG:  SyncML: return message completed
DEBUG:  Finished at 2007-03-19 15:02:32. Packet logged in
/tmp/sync/syncml_server_10.wbxml

DEBUG:  Backend of class SyncML_Backend_Horde created
DEBUG:  Existing session continued:
519bb700184ca0bc7b32ae44cdd4774e
DEBUG:  authorized=1 version=2 msgid=2
source=IMEI:3536400XXXXXXXX
target=https://portal.d
omain.de:443/rpc.php user=userdomain.de
charset=UTF-8 wbxml=1
DEBUG:  created device class SyncML_Device_Nokia
DEBUG:  HandleFinal for state=1
DEBUG:  server create sync output for syncType=./contacts
DEBUG:  Compiling server changes from 2007-03-19 14:53:04 to
2007-03-19 15:02:32
DEBUG:  sending 0 server changes for syncType=./contacts
DEBUG:  Received Final from client.
DEBUG:  Sending Final to client.
DEBUG:  SyncML: return message completed
DEBUG:  Finished at 2007-03-19 15:02:33. Packet logged in
/tmp/sync/syncml_server_11.wbxml

DEBUG:  Backend of class SyncML_Backend_Horde created
DEBUG:  Existing session continued:
519bb700184ca0bc7b32ae44cdd4774e
DEBUG:  authorized=1 version=2 msgid=3
source=IMEI:3536400XXXXXXXX
target=https://portal.d
omain.de:443/rpc.php user=userdomain.de
charset=UTF-8 wbxml=1
DEBUG:  HandleFinal for state=3
DEBUG:  Received Final from client.
DEBUG:  Sending Final to client.
INFO:   Successful sync of ./contacts! Summary: failures=0;
client(Add,Replace,Delete,AddReplaces)=0,0,0,0;
server(Add,Replace,
Delete)=0,0,0
DEBUG:  Finished at 2007-03-19 15:02:34. Packet logged in
/tmp/sync/syncml_server_12.wbxml

this is the third (slow)sync:

DEBUG:  Backend of class SyncML_Backend_Horde created
DEBUG:  New session created:
57fd25739717025f05ccc26b32b8c90c
DEBUG:  checking auth for user=userdomain.de
DEBUG:  authorized=1 version=2 msgid=1
source=IMEI:3536400XXXXXXXX
target=https://portal.d
omain.de:443/rpc.php user=userdomain.de
charset=UTF-8 wbxml=1
DEBUG:  previous sync found for database: ./contacts;
client-ts:
20070319T145033Z
INFO:   client requested sync with anchor ts
20070319T150001Z but
server has timestamp20070319T145033Z on file. Enforcing
SlowSync
DEBUG:  Create new sync for ./contacts; synctype=201
DEBUG:  HandleFinal for state=0
DEBUG:  Received Final from client.
DEBUG:  Sending Final to client.
DEBUG:  SyncML: return message completed
DEBUG:  Finished at 2007-03-19 15:07:34. Packet logged in
/tmp/sync/syncml_server_10.wbxml

DEBUG:  Backend of class SyncML_Backend_Horde created
DEBUG:  Existing session continued:
57fd25739717025f05ccc26b32b8c90c
DEBUG:  authorized=1 version=2 msgid=2
source=IMEI:3536400XXXXXXXX
target=https://portal.d
omain.de:443/rpc.php user=userdomain.de
charset=UTF-8 wbxml=1
DEBUG:  created device class SyncML_Device_Nokia
DEBUG:  Handling client sent Add
DEBUG:  Add: Already exists with
suid=20070319122056.6n75qwqx400oportal.domain.de
DEBUG:  added client entry as
20070319122056.6n75qwqx400oportal.domain.de
[...]
DEBUG:  HandleFinal for state=1
DEBUG:  server create sync output for syncType=./contacts
DEBUG:  Compiling server changes from 1970-01-01 01:00:00 to
2007-03-19 15:07:34
DEBUG:  slowsync-add: 20070319122056.6n75qwqx400oportal.domain.de ignored
[...]
DEBUG:  sending 0 server changes for syncType=./contacts
DEBUG:  Received Final from client.
DEBUG:  Sending Final to client.
DEBUG:  SyncML: return message completed
DEBUG:  Finished at 2007-03-19 15:08:01. Packet logged in
/tmp/sync/syncml_server_18.wbxml

DEBUG:  Backend of class SyncML_Backend_Horde created
DEBUG:  Existing session continued:
57fd25739717025f05ccc26b32b8c90c
DEBUG:  authorized=1 version=2 msgid=10
source=IMEI:3536400XXXXXXXX
target=https://portal.d
omain.de:443/rpc.php user=userdomain.de
charset=UTF-8 wbxml=1
DEBUG:  HandleFinal for state=3
DEBUG:  Received Final from client.
DEBUG:  Sending Final to client.
INFO:   Successful sync of ./contacts! Summary: failures=0;
client(Add,Replace,Delete,AddReplaces)=176,0,0,0;
server(Add,Replac
e,Delete)=0,0,0
DEBUG:  Finished at 2007-03-19 15:08:02. Packet logged in
/tmp/sync/syncml_server_19.wbxml

---snip---

Any suggestions would be greatly appreciated 

-- 
Garvin Gripp
-- 
sync mailing list - Join the hunt: http://horde.org/boun
ties/#sync
Frequently Asked Questions: http://horde.org/faq/
To unsubscribe, mail: sync-unsubscribelists.horde.org

Hi,

there's been an error with my usage of the datatree.
(reappared with a 
datatree checkin from feb 25th.) This is most likely the
cause for the 
errors you've observed.

This should be fixed with
/framework/SyncML/SyncML/Backend/Horde.php rev1.3.
This in cvs since two days ago.
Can you give this a try and report if it's working now?

Thanks,
  Karsten

Garvin Gripp wrote:
> Hi everybody,
> 
> I'm trying desperately getting SyncML to work with a
N73. Actually it
> worked pretty fine for a while, but since a week or so
i am always
> getting slow syncs, resulting in duplicate calendar
entries,
> especially when they are repeating (e.g. birthdays).
> 
> I'm just using contacts-synchronisation for the sake of
simplicity right now,
> using the latest CVS version from this morning, php
error log shows no errors.
> 
> I truncated the horde_syncml_map table and deleted all
syncml-data in
> the setup prior to the following:
> 
> the first (slow-sync) works fine, the second sync is a
fast sync; the
> log shows that the timestamps match. starting with the
third sync i
> only get slow syncs because the timestamps don't match.
See the
> attached syncml_log.txt extracts:
> 
> initial first sync (with empty syncml_map-table):
> 
> DEBUG:  Backend of class SyncML_Backend_Horde created
> DEBUG:  New session created:
82a530bb786584c894fb8fd6f13b6d2f
> DEBUG:  checking auth for user=userdomain.de
> DEBUG:  authorized=1 version=2 msgid=1
source=IMEI:3536400XXXXXXXX target=https:
> //portal.domain.de:443/rpc.php user=userdomain.de
charset
> =UTF-8 wbxml=1
> DEBUG:  SyncML: No info about previous syncs found for
device
> IMEI:3536400XXXXXXXX and database ./contacts
> DEBUG:  Create new sync for ./contacts; synctype=201
> DEBUG:  HandleFinal for state=0
> DEBUG:  Received Final from client.
> DEBUG:  Sending Final to client.
> DEBUG:  SyncML: return message completed
> DEBUG:  Finished at 2007-03-19 14:53:04. Packet logged
in
> /tmp/sync/syncml_server_10.wbxml
> 
> DEBUG:  Backend of class SyncML_Backend_Horde created
> DEBUG:  Existing session continued:
82a530bb786584c894fb8fd6f13b6d2f
> DEBUG:  authorized=1 version=2 msgid=2
source=IMEI:3536400XXXXXXXX target=https:
> //portal.domain.de:443/rpc.php user=userdomain.de
charset
> =UTF-8 wbxml=1
> DEBUG:  created device class SyncML_Device_Nokia
> DEBUG:  Handling client sent Add
> DEBUG:  Add: Already exists with
> uid=20070319122056.6n75qwqx400oportal.domain.de
> DEBUG:  added client entry as
20070319122056.6n75qwqx400oportal.domain.d
> e
> DEBUG:  Handling client sent Add
> DEBUG:  Add: Already exists with
> suid=20070319122056.6uo564p393q0portal.domain.de
> DEBUG:  added client entry as
20070319122056.6uo564p393q0portal.domain.d
> e
> [...]
> DEBUG:  HandleFinal for state=1
> DEBUG:  server create sync output for
syncType=./contacts
> DEBUG:  Compiling server changes from 1970-01-01
01:00:00 to 2007-03-19 14:53:04
> DEBUG:  slowsync-add: 20070319122056.6n75qwqx400oportal.domain.de ignored
> DEBUG:  slowsync-add: 20070319122056.6uo564p393q0portal.domain.de ignored
> [...]
> DEBUG:  sending 0 server changes for
syncType=./contacts
> DEBUG:  Received Final from client.
> DEBUG:  Sending Final to client.
> DEBUG:  SyncML: return message completed
> DEBUG:  Finished at 2007-03-19 14:53:31. Packet logged
in
> /tmp/sync/syncml_server_18.wbxml
> 
> DEBUG:  Backend of class SyncML_Backend_Horde created
> DEBUG:  Existing session continued:
82a530bb786584c894fb8fd6f13b6d2f
> DEBUG:  authorized=1 version=2 msgid=10
source=IMEI:3536400XXXXXXXX
> target=https://portal.d
omain.de:443/rpc.php user=userdomain.de
> charset=UTF-8 wbxml=1
> DEBUG:  HandleFinal for state=3
> DEBUG:  Received Final from client.
> DEBUG:  Sending Final to client.
> INFO:   Successful sync of ./contacts! Summary:
failures=0;
> client(Add,Replace,Delete,AddReplaces)=176,0,0,0;
server(Add,Replac
> e,Delete)=0,0,0
> DEBUG:  Finished at 2007-03-19 14:53:32. Packet logged
in
> /tmp/sync/syncml_server_19.wbxml
> 
> 
> this is the second (successful) sync:
> 
> DEBUG:  Backend of class SyncML_Backend_Horde created
> DEBUG:  New session created:
519bb700184ca0bc7b32ae44cdd4774e
> DEBUG:  checking auth for user=userdomain.de
> DEBUG:  authorized=1 version=2 msgid=1
source=IMEI:3536400XXXXXXXX
> target=https://portal.d
omain.de:443/rpc.php user=userdomain.de
> charset=UTF-8 wbxml=1
> DEBUG:  previous sync found for database: ./contacts;
client-ts:
> 20070319T145033Z
> DEBUG:  SyncML: Anchor match, TwoWaySync since
20070319T145033Z
> DEBUG:  Create new sync for ./contacts; synctype=200
> DEBUG:  HandleFinal for state=0
> DEBUG:  Received Final from client.
> DEBUG:  Sending Final to client.
> DEBUG:  SyncML: return message completed
> DEBUG:  Finished at 2007-03-19 15:02:32. Packet logged
in
> /tmp/sync/syncml_server_10.wbxml
> 
> DEBUG:  Backend of class SyncML_Backend_Horde created
> DEBUG:  Existing session continued:
519bb700184ca0bc7b32ae44cdd4774e
> DEBUG:  authorized=1 version=2 msgid=2
source=IMEI:3536400XXXXXXXX
> target=https://portal.d
omain.de:443/rpc.php user=userdomain.de
> charset=UTF-8 wbxml=1
> DEBUG:  created device class SyncML_Device_Nokia
> DEBUG:  HandleFinal for state=1
> DEBUG:  server create sync output for
syncType=./contacts
> DEBUG:  Compiling server changes from 2007-03-19
14:53:04 to 2007-03-19 15:02:32
> DEBUG:  sending 0 server changes for
syncType=./contacts
> DEBUG:  Received Final from client.
> DEBUG:  Sending Final to client.
> DEBUG:  SyncML: return message completed
> DEBUG:  Finished at 2007-03-19 15:02:33. Packet logged
in
> /tmp/sync/syncml_server_11.wbxml
> 
> DEBUG:  Backend of class SyncML_Backend_Horde created
> DEBUG:  Existing session continued:
519bb700184ca0bc7b32ae44cdd4774e
> DEBUG:  authorized=1 version=2 msgid=3
source=IMEI:3536400XXXXXXXX
> target=https://portal.d
omain.de:443/rpc.php user=userdomain.de
> charset=UTF-8 wbxml=1
> DEBUG:  HandleFinal for state=3
> DEBUG:  Received Final from client.
> DEBUG:  Sending Final to client.
> INFO:   Successful sync of ./contacts! Summary:
failures=0;
> client(Add,Replace,Delete,AddReplaces)=0,0,0,0;
server(Add,Replace,
> Delete)=0,0,0
> DEBUG:  Finished at 2007-03-19 15:02:34. Packet logged
in
> /tmp/sync/syncml_server_12.wbxml
> 
> this is the third (slow)sync:
> 
> DEBUG:  Backend of class SyncML_Backend_Horde created
> DEBUG:  New session created:
57fd25739717025f05ccc26b32b8c90c
> DEBUG:  checking auth for user=userdomain.de
> DEBUG:  authorized=1 version=2 msgid=1
source=IMEI:3536400XXXXXXXX
> target=https://portal.d
omain.de:443/rpc.php user=userdomain.de
> charset=UTF-8 wbxml=1
> DEBUG:  previous sync found for database: ./contacts;
client-ts:
> 20070319T145033Z
> INFO:   client requested sync with anchor ts
20070319T150001Z but
> server has timestamp20070319T145033Z on file. Enforcing
SlowSync
> DEBUG:  Create new sync for ./contacts; synctype=201
> DEBUG:  HandleFinal for state=0
> DEBUG:  Received Final from client.
> DEBUG:  Sending Final to client.
> DEBUG:  SyncML: return message completed
> DEBUG:  Finished at 2007-03-19 15:07:34. Packet logged
in
> /tmp/sync/syncml_server_10.wbxml
> 
> DEBUG:  Backend of class SyncML_Backend_Horde created
> DEBUG:  Existing session continued:
57fd25739717025f05ccc26b32b8c90c
> DEBUG:  authorized=1 version=2 msgid=2
source=IMEI:3536400XXXXXXXX
> target=https://portal.d
omain.de:443/rpc.php user=userdomain.de
> charset=UTF-8 wbxml=1
> DEBUG:  created device class SyncML_Device_Nokia
> DEBUG:  Handling client sent Add
> DEBUG:  Add: Already exists with
> suid=20070319122056.6n75qwqx400oportal.domain.de
> DEBUG:  added client entry as
20070319122056.6n75qwqx400oportal.domain.de
> [...]
> DEBUG:  HandleFinal for state=1
> DEBUG:  server create sync output for
syncType=./contacts
> DEBUG:  Compiling server changes from 1970-01-01
01:00:00 to 2007-03-19 15:07:34
> DEBUG:  slowsync-add: 20070319122056.6n75qwqx400oportal.domain.de ignored
> [...]
> DEBUG:  sending 0 server changes for
syncType=./contacts
> DEBUG:  Received Final from client.
> DEBUG:  Sending Final to client.
> DEBUG:  SyncML: return message completed
> DEBUG:  Finished at 2007-03-19 15:08:01. Packet logged
in
> /tmp/sync/syncml_server_18.wbxml
> 
> DEBUG:  Backend of class SyncML_Backend_Horde created
> DEBUG:  Existing session continued:
57fd25739717025f05ccc26b32b8c90c
> DEBUG:  authorized=1 version=2 msgid=10
source=IMEI:3536400XXXXXXXX
> target=https://portal.d
omain.de:443/rpc.php user=userdomain.de
> charset=UTF-8 wbxml=1
> DEBUG:  HandleFinal for state=3
> DEBUG:  Received Final from client.
> DEBUG:  Sending Final to client.
> INFO:   Successful sync of ./contacts! Summary:
failures=0;
> client(Add,Replace,Delete,AddReplaces)=176,0,0,0;
server(Add,Replac
> e,Delete)=0,0,0
> DEBUG:  Finished at 2007-03-19 15:08:02. Packet logged
in
> /tmp/sync/syncml_server_19.wbxml
> 
> ---snip---
> 
> Any suggestions would be greatly appreciated 
> 


-- 
sync mailing list - Join the hunt: http://horde.org/boun
ties/#sync
Frequently Asked Questions: http://horde.org/faq/
To unsubscribe, mail: sync-unsubscribelists.horde.org

On 3/20/07, Karsten Fourmont <fourmontgmx.de> wrote:
>
> This should be fixed with
> /framework/SyncML/SyncML/Backend/Horde.php rev1.3.
> This in cvs since two days ago.
> Can you give this a try and report if it's working
now?
>

I updated from cvs yesterday, that didnt solve my problem,
but I'll do
an update again later.

I have the suspicion that there are inconsistencies in my
data-tree,
when i try to delete the syncML data in the Settings Menu i
get
different error messages everytime i click on that button:
Parents not found: contacts does not exist
Parents not found: IMEI_3536400XXXXXXXX does not exist
and then, finally: 1 Sync data deleted.

Thanks for looking into this.

-- 
Garvin Gripp
-- 
sync mailing list - Join the hunt: http://horde.org/boun
ties/#sync
Frequently Asked Questions: http://horde.org/faq/
To unsubscribe, mail: sync-unsubscribelists.horde.org

Hi,

Updated from cvs couple of minutes agot, that unfortunately
didn't do
the trick. I truncated syncml_map, and all horde.syncml
entries in the
datatree, and clicked the "clear all syncml data"
button several times
(maybe in a different order)

Still a slow sync the 3rd time.

Any more hints would be greatly appreciated.

On 3/20/07, Karsten Fourmont <fourmontgmx.de> wrote:
> It should now display the timestamps again. A broken
datatree results in
> duplicate entries with same Device/Database combination
but different
> timestamps. Delete the duplicate entries or do a
"Delete all SyncML data".
>

-- 
Garvin Gripp
-- 
sync mailing list - Join the hunt: http://horde.org/boun
ties/#sync
Frequently Asked Questions: http://horde.org/faq/
To unsubscribe, mail: sync-unsubscribelists.horde.org

Hi,

Do the timestamps appear in the options page after a
succesful sync?

Like this:
Device	Database	Server-TS	Client-TS	Delete
DUMMY	calendar	2007-03-19 11:55	20070319T105502Z

Karsten

Garvin Gripp wrote:
> Hi,
> 
> Updated from cvs couple of minutes agot, that
unfortunately didn't do
> the trick. I truncated syncml_map, and all horde.syncml
entries in the
> datatree, and clicked the "clear all syncml
data" button several times
> (maybe in a different order)
> 
> Still a slow sync the 3rd time.
> 
> Any more hints would be greatly appreciated.
> 


-- 
sync mailing list - Join the hunt: http://horde.org/boun
ties/#sync
Frequently Asked Questions: http://horde.org/faq/
To unsubscribe, mail: sync-unsubscribelists.horde.org