[Synce-devel] Troubling syncing, exceptions based on wrong PCData

[Guido Diepen]

Hi again :)

unfortunately, nothing ever goes easy and currently I am just running in all
kinds of problems. Got the partnership to work and created a sync-group after
which I decided it was time to try the real syncing :)

Unfortunately this went wrong and the PDA states that it wants to sync 107
contacts to the computer, but it just hangs there. Below I attached the
output of the sync-egine that might be relevant.

Again, the device I use is a wm6 device, though I don't think that that causes
the problem here. Furthermore, the SVN revision of sync-engine I now use is
3059. If more info is needed, please let me know.


Regards,

Guido Diepen

PS: I attached everything from the log from the moment I initiated the sync,
(could be that some useful info is in this part) the most important stuff is
at the bottom though :)


2007-11-28 16:54:26,712 INFO engine.syncengine.SyncEngine : Synchronize:
manual sync triggered
2007-11-28 16:54:26,713 INFO engine.syncengine.SyncEngine : Synchronize:
starting manual sync with partnership P1: id=0x5f0288d,
guid="{7F9E767E-9DEA-0DDD-27B1-62FD5CEAB63A}", hostname="cartman",
name="Linux desktop", sync_items=[ Contacts, Calendar, Tasks ]
2007-11-28 16:54:26,713 INFO engine.partnerships.Partnership : loading itemDB
for item 0
2007-11-28 16:54:26,714 INFO engine.partnerships.Partnership : loading itemDB
for item 1
2007-11-28 16:54:26,714 INFO engine.partnerships.Partnership : loading itemDB
for item 7
2007-11-28 16:54:26,714 INFO engine.syncengine.SyncEngine : Synchronize:
itemDB loaded
2007-11-28 16:54:26,715 INFO engine.syncengine.SyncEngine : Synchronize:
leaving method
2007-11-28 16:54:26,734 DEBUG engine.synchandler.SyncHandler : run: sending
request to device
<sync xmlns="http://schemas.microsoft.com/as/2004/core" type="Interactive">
<partner id="{7F9E767E-9DEA-0DDD-27B1-62FD5CEAB63A}"/>
</sync>
2007-11-28 16:54:26,856 DEBUG engine.synchandler.SyncHandler : run: performing
synchronization
2007-11-28 16:54:26,929 INFO engine.airsync.AirsyncServer : do_POST: received
Status command
2007-11-28 16:54:26,930 DEBUG engine.airsync.AirsyncServer : _handle_status:
request document is
<?xml version="1.0" encoding="utf-8"?>
<SyncStatus>
<SyncBegin Partner="" Datatype=""/>
</SyncStatus>

2007-11-28 16:54:26,930 DEBUG engine.airsync.AirsyncServer :
_send_empty_response: Emitting response 200 code to client
2007-11-28 16:54:26,930 DEBUG engine.airsync.AirsyncServer : HTTP
Request: "POST /Microsoft-Server-ActiveSync/SyncStat.dll HTTP/1.1" 200 -
2007-11-28 16:54:26,931 DEBUG engine.airsync.AirsyncServer :
_send_empty_response: Finished emitting response 200 code to client
2007-11-28 16:54:27,298 INFO engine.airsync.AirsyncServer : do_POST: received
Status command
2007-11-28 16:54:27,299 DEBUG engine.airsync.AirsyncServer : _handle_status:
request document is
<?xml version="1.0" encoding="utf-8"?>
<SyncStatus>
<SyncBegin Partner="{7F9E767E-9DEA-0DDD-27B1-62FD5CEAB63A}" Datatype=""/>
</SyncStatus>

2007-11-28 16:54:27,299 DEBUG engine.airsync.AirsyncServer :
_send_empty_response: Emitting response 200 code to client
2007-11-28 16:54:27,300 DEBUG engine.airsync.AirsyncServer : HTTP
Request: "POST /Microsoft-Server-ActiveSync/SyncStat.dll HTTP/1.1" 200 -
2007-11-28 16:54:27,300 DEBUG engine.airsync.AirsyncServer :
_send_empty_response: Finished emitting response 200 code to client
2007-11-28 16:54:27,463 DEBUG engine.airsync.AirsyncServer :
_send_empty_response: Emitting response 200 code to client
2007-11-28 16:54:27,463 DEBUG engine.airsync.AirsyncServer : HTTP
Request: "OPTIONS /Microsoft-Server-ActiveSync?User=DEFAULT&DeviceId=B812A5251606DFD1F816713B3FBFA42D&DeviceType=PocketPC
HTTP/1.1" 200 -
2007-11-28 16:54:27,463 DEBUG engine.airsync.AirsyncServer :
_send_empty_response: Finished emitting response 200 code to client
2007-11-28 16:54:28,393 INFO engine.airsync.AirsyncServer : do_POST: received
Status command
2007-11-28 16:54:28,394 DEBUG engine.airsync.AirsyncServer : _handle_status:
request document is
<?xml version="1.0" encoding="utf-8"?>
<SyncStatus>
<Status Partner="{7F9E767E-9DEA-0DDD-27B1-62FD5CEAB63A}">
<Progress value="0"/>
</Status>
<Status Partner="{7F9E767E-9DEA-0DDD-27B1-62FD5CEAB63A}">
<Total value="100"/>
</Status>
<Status Partner="{7F9E767E-9DEA-0DDD-27B1-62FD5CEAB63A}">
<StatusString type="Status" value="Wijzigingen zoeken"/>
</Status>
</SyncStatus>

2007-11-28 16:54:28,396 DEBUG engine.airsync.AirsyncServer :
_send_empty_response: Emitting response 200 code to client
2007-11-28 16:54:28,397 DEBUG engine.airsync.AirsyncServer : HTTP
Request: "POST /Microsoft-Server-ActiveSync/SyncStat.dll HTTP/1.1" 200 -
2007-11-28 16:54:28,397 DEBUG engine.airsync.AirsyncServer :
_send_empty_response: Finished emitting response 200 code to client
2007-11-28 16:54:28,463 INFO engine.airsync.AirsyncServer : do_POST: received
GetItemEstimate command
2007-11-28 16:54:28,463 DEBUG engine.airsync.AirsyncServer :
_read_xml_request: converting request from wbxml
2007-11-28 16:54:28,464 DEBUG engine.airsync.AirsyncServer :
_handle_get_item_estimate: request document is
<?xml version="1.0" encoding="utf-8"?>
<!DOCTYPE AirSync PUBLIC "-//AIRSYNC//DTD
AirSync//EN" "http://www.microsoft.com/">
<GetItemEstimate xmlns="http://synce.org/formats/airsync_wm5/getitemestimate">
<Collections>
<Collection>
<Class>Contacts</Class>
<CollectionId>{7CBE2AFE-74D6-2995-D40B-6DD4B8FECDC4}</CollectionId>
<FilterType
xmlns="http://synce.org/formats/airsync_wm5/airsync">0</FilterType>
<SyncKey
xmlns="http://synce.org/formats/airsync_wm5/airsync">{7CBE2AFE-74D6-2995-D40B-6DD4B8FECDC4}
1</SyncKey>
</Collection>
<Collection>
<Class>Calendar</Class>
<CollectionId>{746F9B9B-9E3F-E932-CD79-D42F333EF242}</CollectionId>
<FilterType
xmlns="http://synce.org/formats/airsync_wm5/airsync">4</FilterType>
<SyncKey
xmlns="http://synce.org/formats/airsync_wm5/airsync">{746F9B9B-9E3F-E932-CD79-D42F333EF242}
1</SyncKey>
</Collection>
<Collection>
<Class>Tasks</Class>
<CollectionId>{7EF93EA0-82A7-EA38-55D8-D4E771CC1B45}</CollectionId>
<FilterType
xmlns="http://synce.org/formats/airsync_wm5/airsync">0</FilterType>
<SyncKey
xmlns="http://synce.org/formats/airsync_wm5/airsync">{7EF93EA0-82A7-EA38-55D8-D4E771CC1B45}
1</SyncKey>
</Collection>
</Collections>
</GetItemEstimate>

2007-11-28 16:54:28,465 DEBUG engine.airsync.AirsyncServer :
_handle_get_item_estimate: response document is
<?xml version="1.0" encoding="utf-8"?>
<!DOCTYPE AirSync PUBLIC "-//AIRSYNC//DTD
AirSync//EN" "http://www.microsoft.com/">
<GetItemEstimate xmlns="http://synce.org/formats/airsync_wm5/getitemestimate">
<Response>
<Status>1</Status>
<Collection>
<Class>Contacts</Class>
<CollectionId>{7CBE2AFE-74D6-2995-D40B-6DD4B8FECDC4}</CollectionId>
<Estimate>0</Estimate>
</Collection>
</Response>
<Response>
<Status>1</Status>
<Collection>
<Class>Calendar</Class>
<CollectionId>{746F9B9B-9E3F-E932-CD79-D42F333EF242}</CollectionId>
<Estimate>0</Estimate>
</Collection>
</Response>
<Response>
<Status>1</Status>
<Collection>
<Class>Tasks</Class>
<CollectionId>{7EF93EA0-82A7-EA38-55D8-D4E771CC1B45}</CollectionId>
<Estimate>0</Estimate>
</Collection>
</Response>
</GetItemEstimate>

2007-11-28 16:54:28,466 DEBUG engine.airsync.AirsyncServer :
_send_wbxml_response: Emitting response 200 code to client
2007-11-28 16:54:28,466 DEBUG engine.airsync.AirsyncServer : HTTP
Request: "POST /Microsoft-Server-ActiveSync?User=DEFAULT&DeviceId=B812A5251606DFD1F816713B3FBFA42D&DeviceType=PocketPC&Cmd=GetItemEstimate
HTTP/1.1" 200 -
2007-11-28 16:54:28,466 DEBUG engine.airsync.AirsyncServer :
_send_wbxml_response: Finished emitting response 200 code to client
2007-11-28 16:54:28,467 DEBUG engine.airsync.AirsyncServer :
_send_wbxml_response: Emitting wbxml (length = 209)
2007-11-28 16:54:28,467 DEBUG engine.airsync.AirsyncServer :
_send_wbxml_response: Finished emitting wbxml
2007-11-28 16:54:28,560 INFO engine.airsync.AirsyncServer : do_POST: received
Status command
2007-11-28 16:54:28,561 DEBUG engine.airsync.AirsyncServer : _handle_status:
request document is
<?xml version="1.0" encoding="utf-8"?>
<SyncStatus>
<SyncBegin Partner="{7F9E767E-9DEA-0DDD-27B1-62FD5CEAB63A}"
Datatype="{0DD8685C-E272-4FCB-9ECF-2EAD7EA2497B}"/>
</SyncStatus>

2007-11-28 16:54:28,561 DEBUG engine.airsync.AirsyncServer :
_send_empty_response: Emitting response 200 code to client
2007-11-28 16:54:28,562 DEBUG engine.airsync.AirsyncServer : HTTP
Request: "POST /Microsoft-Server-ActiveSync/SyncStat.dll HTTP/1.1" 200 -
2007-11-28 16:54:28,562 DEBUG engine.airsync.AirsyncServer :
_send_empty_response: Finished emitting response 200 code to client
2007-11-28 16:54:29,508 INFO engine.airsync.AirsyncServer : do_POST: received
Status command
2007-11-28 16:54:29,510 DEBUG engine.airsync.AirsyncServer : _handle_status:
request document is
<?xml version="1.0" encoding="utf-8"?>
<SyncStatus>
<Status Partner="{7F9E767E-9DEA-0DDD-27B1-62FD5CEAB63A}">
<StatusString type="Status" value="0/107"/>
</Status>
</SyncStatus>

2007-11-28 16:54:29,511 DEBUG engine.airsync.AirsyncServer :
_send_empty_response: Emitting response 200 code to client
2007-11-28 16:54:29,511 DEBUG engine.airsync.AirsyncServer : HTTP
Request: "POST /Microsoft-Server-ActiveSync/SyncStat.dll HTTP/1.1" 200 -
2007-11-28 16:54:29,512 DEBUG engine.airsync.AirsyncServer :
_send_empty_response: Finished emitting response 200 code to client
2007-11-28 16:54:56,786 INFO engine.airsync.AirsyncServer : do_POST: received
Sync command
2007-11-28 16:54:57,130 DEBUG engine.airsync.AirsyncServer :
_read_xml_request: converting request from wbxml
Entity: line 1: parser error : PCDATA invalid Char value 29
5/contacts"/><NickName
xmlns="http://synce.org/formats/airsync_wm5/contacts2">ޠ

^
Entity: line 1: parser error : PCDATA invalid Char value 29
/contacts"/><NickName xmlns="http://synce.org/formats/airsync_wm5/contacts2">ॠ

^
Traceback (most recent call last):
File "SocketServer.py", line 222, in handle_request
self.process_request(request, client_address)
File "SocketServer.py", line 241, in process_request
self.finish_request(request, client_address)
File "SocketServer.py", line 254, in finish_request
self.RequestHandlerClass(request, client_address, self)
File "/home/guido/syncing/sync-engine/SyncEngine/airsync.py", line 62, in
__init__
BaseHTTPServer.BaseHTTPRequestHandler.__init__(self, request,
client_address, server)
File "SocketServer.py", line 521, in __init__
self.handle()
File "BaseHTTPServer.py", line 316, in handle
self.handle_one_request()
File "BaseHTTPServer.py", line 310, in handle_one_request
method()
File "/home/guido/syncing/sync-engine/SyncEngine/airsync.py", line 159, in
do_POST
self._handle_sync()
File "/home/guido/syncing/sync-engine/SyncEngine/airsync.py", line 179, in
_handle_sync
req_doc = self._read_xml_request()
File "/home/guido/syncing/sync-engine/SyncEngine/airsync.py", line 117, in
_read_xml_request
return libxml2.parseDoc(req)
File "/var/lib/python-support/python2.4/libxml2.py", line 1264, in parseDoc
if ret is None:raise parserError('xmlParseDoc() failed')
parserError: xmlParseDoc() failed
----------------------------------------
Exception happened during processing of request from ('169.254.2.1', 1169)
----------------------------------------
2007-11-28 16:54:57,268 INFO engine.airsync.AirsyncServer : do_POST: received
Status command
2007-11-28 16:54:57,268 DEBUG engine.airsync.AirsyncServer : _handle_status:
request document is
<?xml version="1.0" encoding="utf-8"?>