Error 500

[marcb]

Ich habe den Server laut der C't Anleitung installiert.
Die Syncronisation mit dem Test-Client und mit meine Handy (Siemens-BenQ SL75) funktioniert auch ohne Probleme.
Nur wenn ich den Server mit dem SyncML-Plugin von Multisync abgleichen will kommt folgenden Fehlermeldung:

linux:~/sync_cmdline# ./syncserv_xpt_odbc
Synthesis Sync Server 2.1.1.28 (standalone,ODBC + plugin)

- Limited to 1 simultaneous sync sessions

- Config file read from './syncserv_odbc.xml'
- Debug log path: /var/log/sysync/ (SEPARATE log file)
- starting HTTP server on port 88

Started new SyncML session (server id=832040034465498349)
> SyncML message #1 received from '3F40F8CB43A9'
< SyncML message #1 sent to '3F40F8CB43A9'
Terminated SyncML session (server id=832040034465498349)


Started new SyncML session (server id=832321509439587565)
> SyncML message #1 received from '3F40F8CB43A9'
- Remote alerts (200): two-way normal sync for './events' (source='calendar')
- switched to SlowSync because of Sync Anchor mismatch
< SyncML message #1 sent to '3F40F8CB43A9'
> SyncML message #2 received from '3F40F8CB43A9'
Session aborted because of SyncML error code 500


- Sync Statistics for 'events' (./events), slow sync
  ************ Failed with status code=500

Terminated SyncML session (server id=832321509439587565)

Liegt das am Multisync Client? Habe auch schon mehrere Möglichkeiten ausprobiert.

[luz]

Originally Posted by marcb

Nur wenn ich den Server mit dem SyncML-Plugin von Multisync abgleichen will kommt folgenden Fehlermeldung:
...
Liegt das am Multisync Client? Habe auch schon mehrere Möglichkeiten ausprobiert.

Error 500 sagt wenig aus, das heisst einfach "Fehler". Ein Blick in die Logfiles könnte Genaueres zu Tage bringen. Am Besten das Logfile in einem Texteditor öffnen und nach "Warning" suchen. Da findet sich der Error 500 und aus dem Kontext wird vielleicht schon klar, an was es liegen könnte - oder dann hier posten...

[marcb]

Hier ein Auszug aus der Log-Datei. Ich kann damit aber nicht viel anfangen.

    - Source (Remote party): URI='3F40F8CB43A9' DisplayName=''
    - Response to be sent to URI='[none specified, back to source]'
    - Target (Local party) : URI='http://192.168.1.70:88/sync?sessionid=6347542203108181233' DisplayName=''
--> SyncHdr: finished execution -> deleting
--> SyncHdr: deleted, (incoming MsgID=2, CmdID=0)
New message: Executing 0 delayed commands
0 delayed commands could not yet be executed and are left in the queue for next message
New package: Sending 0 commands that were generated earlier for this package
--> Status: ---------------> started processing (incoming MsgID=2, CmdID=1)
--> Status: RECEIVED STATUS 200 for command 'SyncHdr' (outgoing MsgID=1, CmdID=0)
--> Status: - TargetRef = '3F40F8CB43A9'
--> Status: - SourceRef = 'http://192.168.1.70:88/sync?sessionid=6347542203108181233'
--> No command found for status -> ignoring
--> Status: deleted, (incoming MsgID=2, CmdID=1)
--------------- Ignoring all commands in this message (after 0 sec. request processing, 0 sec. total) with Status 514 (0=none) from here on
events: *************** Warning: Datastore flagged aborted (after 0 sec. request processing, 0 sec. total) with REMOTE Status 500
*************** Warning: Session flagged aborted with Reason Status 500 *****************
events: TCustDBDataStore::endOfSync, irregular end of sync session
events: >>>>>>>>>>>>> SQL for Log Entry Write:
events: INSERT INTO SYNC_LOG (         SYNCTIME,DS_NAME,DS_REMOTE_PATH,DS_LOCAL_PATH,DEV_KEY,SYNC_STATUS,SYNC_MODE,SYNC_TYPE,         SESSION_ID,FOLDERKEY,TARGETKEY,USERNAME,USERKEY,LOC_ADDED,REM_ADDED,LOC_DELETED,REM_DELETED,LOC_UPDATED,         REM_UPDATED,SLOWSYNC_MATCHES,SERVER_WON,CLIENT_WON,DUPLICATED,
    SESSIONBYTES_IN,SESSIONBYTES_OUT,DATABYTES_IN,DATABYTES_OUT        ) VALUES (         {ts '2006-08-27 16:46:06'},'events','calendar','./events','3',500,0,2,'6347542203108181233',1,2,'test',1,         0,0,0,0,0,0,0,0,0,0,         5041,6507,0,0        )
events:
events: Sync Statistics for 'events' (./events), slow sync
events: ************ Failed with status code=500
events: ==================================================
events:                              on Server   on Client
events: Added:                               0           0
events: Deleted:                             0           0
events: Updated:                             0           0
events: SlowSync Matches:                    0
events: Server won Conflicts:                0
events: Client won Conflicts:                0
events: Conflicts with Duplication:          0
events:
events: Content Data Bytes sent:             0
events: Content Data Bytes received:         0
events:
events: Duration of sync [seconds]:          0
events: ************ Warning: Session aborted, statistics are  incomplete!!
events:
Never received status for command 'Results', (outgoing MsgID=1, CmdID=5)
<-- Results: deleted, (outgoing MsgID=1, CmdID=5)
Never received status for command 'Alert', (outgoing MsgID=1, CmdID=6)
<-- Alert: deleted, (outgoing MsgID=1, CmdID=6)
Never received status for command 'SyncHdr', (outgoing MsgID=2, CmdID=0)
<-- SyncHdr: deleted, (outgoing MsgID=2, CmdID=0)
Session data transfer statistics: incoming bytes=5041, outgoing bytes=6507
<-- Status: deleted, (outgoing MsgID=0, CmdID=0)
<-- Status: deleted, (outgoing MsgID=0, CmdID=0)
<-- Status: deleted, (outgoing MsgID=0, CmdID=0)
<-- Status: deleted, (outgoing MsgID=0, CmdID=0)

So wie ich das sehe kommt der Fehler in den folgenden Zeilen:

--------------- Ignoring all commands in this message (after 0 sec. request processing, 0 sec. total) with Status 514 (0=none) from here on
events: *************** Warning: Datastore flagged aborted (after 0 sec. request processing, 0 sec. total) with REMOTE Status 500
*************** Warning: Session flagged aborted with Reason Status 500 *****************

[luz]

Das sieht danach aus, als ob der Error 500 von Multisync käme (um sicher zu sein, müsste ich das ganze Log sehen). Da dies ein genereller "etwas-ist-faul"-Error ist, bricht der Server die Session ab. Die Frage ist aber, weshalb Multisync überhaupt einen Error 500 produziert.

Wie sieht es im globalen log (xpt_odbc.log) aus?

[marcb]

Hier der Inhalt der xpt_odbc.log:

====== Mon Aug 28 16:11:24 2006

[2006-08-28 16:11:24] ====== New Request passed to TXPTSessionDispatch::handleXPTRequest, RequestCount=1
[2006-08-28 16:11:24] client requests Connection CLOSE
[2006-08-28 16:11:24] ===> Content-Type = 'application/vnd.syncml+xml'
[2006-08-28 16:11:24] ===> received Contents-Type='application/vnd.syncml+xml', used encoding='XML'
[2006-08-28 16:11:24] Document name is: /sync/
[2006-08-28 16:11:24] Now creating new session
[2006-08-28 16:11:24] Session created: local session ID='8990873709400573170', not yet in session list
[2006-08-28 16:11:24] TSyncServer::EndRequest returned true -> terminating and deleting session now
[2006-08-28 16:11:24] TSyncServer::~TSyncServer: Deleted SyncML session (server id=8990873709400573170)
[2006-08-28 16:11:24] Terminated and deleted session
[2006-08-28 16:11:24] -------------------------------------------
[2006-08-28 16:11:24] Active Sessions (0):
[2006-08-28 16:11:24] -------------------------------------------
[2006-08-28 16:11:24]

====== Mon Aug 28 16:11:24 2006

[2006-08-28 16:11:24] ====== New Request passed to TXPTSessionDispatch::handleXPTRequest, RequestCount=2
[2006-08-28 16:11:25] client requests Connection CLOSE
[2006-08-28 16:11:25] ===> Content-Type = 'application/vnd.syncml+xml'
[2006-08-28 16:11:25] ===> received Contents-Type='application/vnd.syncml+xml', used encoding='XML'
[2006-08-28 16:11:25] Document name is: /sync/
[2006-08-28 16:11:25] Now creating new session
[2006-08-28 16:11:25] Session created: local session ID='8990873710152926450', not yet in session list
[2006-08-28 16:11:25] TSyncServer::EndRequest returned false -> just leave session
[2006-08-28 16:11:25] -------------------------------------------
[2006-08-28 16:11:25] Active Sessions (1):
[2006-08-28 16:11:25] - 8990873710152926450 :Remote URI=664583E90A71, Local URI=http://192.168.1.70:88/sync/, LastUsed=2006-08-28 14:11:25
[2006-08-28 16:11:25] -------------------------------------------
[2006-08-28 16:11:25]

====== Mon Aug 28 16:11:25 2006

[2006-08-28 16:11:25] ====== New Request passed to TXPTSessionDispatch::handleXPTRequest, RequestCount=3
[2006-08-28 16:11:25]

====== Mon Aug 28 16:11:25 2006

[2006-08-28 16:11:25] ====== New Request passed to TXPTSessionDispatch::handleXPTRequest, RequestCount=4
[2006-08-28 16:11:25] client requests Connection CLOSE
[2006-08-28 16:11:25] ===> Content-Type = 'application/vnd.syncml+xml'
[2006-08-28 16:11:25] ===> received Contents-Type='application/vnd.syncml+xml', used encoding='XML'
[2006-08-28 16:11:25] Document name is: /sync/?sessionid=8990873710152926450
[2006-08-28 16:11:25] Document name contained cgi session id = '8990873710152926450'
[2006-08-28 16:11:25] TSyncSessionDispatch::StartMessage called with transport layer session ID='8990873710152926450'
[2006-08-28 16:11:25] Session found by SessionID=8990873710152926450
[2006-08-28 16:11:25] Entering found session...
[2006-08-28 16:11:25] Session entered
[2006-08-28 16:11:25] smlProcessData failed, returned err=0x2008, killing session
[2006-08-28 16:11:25] TSyncServer::~TSyncServer: Deleted SyncML session (server id=8990873710152926450)
[2006-08-28 16:11:25] No response to send, omitted calling xptSendData/xptSendComplete

Werde mal gucken ob ich einen fehler bei MultiSync finde.

[luz]

[2006-08-28 16:11:25] smlProcessData failed, returned err=0x2008, killing session

An dieser Stelle scheitert das Ganze. Der Error 0x2008 bedeutet nämlich, dass es einen ganz grundlegenden Syntax-Fehler in den Daten hat, die MultiSync sendet, und diese deshalb nicht mal ansatzweise decodiert werden können.

Offenbar handelt es sich um das erste Command in der Message 2 von MultiSync zum Server (das geht aus der Stelle hervor, wo im Session-Log der Abbruch stattfindet, nämlich nach dem Header der Message 2).
Um rauszukriegen, was das sein könnte, müssten wir die gesendete Message 1:1 haben. Das geht einfach indem in der Config <msgdump> im Abschnitt <debug> eingeschaltet wird.

Da MultiSync ja offenbar in XML (und nicht WBXML) sendet, sind diese Messages einigermassen lesbar, und die Message mit <MsgID>2</MsgID> sollte zu finden sein, und das erste Command im <SyncBody> ist dann dort von Interesse.

[marcb]

Wo finde ich denn dann die Message?
Irgendwie sehen die Log-Files noch genau so aus wie ohne msgdump.

Ich muss doch da dann <msgdump>yes</msgdump> im Konfig-File stehen haben, oder?

[luz]

Das <msgdump> existiert schon in der Beispiel-Konfig, innerhalb des <debug>-Abschnitts, ist aber auf "no" gesetzt. Wahrscheinlich haben Sie jetzt zwei <msgdump>s, wobei das zweite das erste übersteuert. Wenn es wirklich aktiv ist, dann sehen sie zusätzliche Files von der Art "xpt_odbc_reqXXX_incoming.sml", das sind die Messagedumps.

Weil MultiSync XML (und nicht das binäre WBXML) verwendet, können Sie die einfach in .xml umbenennen und dann z.B. mit Firefox oder IE schön darstellen lassen.

[marcb]

Hier der Inhalt:

−
	<SyncML>
−
	<SyncHdr>
<VerDTD>1.1</VerDTD>
<VerProto>SyncML/1.1</VerProto>
<SessionID>1</SessionID>
<MsgID>2</MsgID>
−
	<Target>
−
	<LocURI>
http://192.168.1.70:88/sync/?sessionid=3514778038247113972
</LocURI>
</Target>
−
	<Source>
<LocURI>664583E90A71</LocURI>
</Source>
</SyncHdr>
−
	<SyncBody>
−
	<Status>
<CmdID>1</CmdID>
<MsgRef>1</MsgRef>
<CmdRef>0</CmdRef>
<Cmd>SyncHdr</Cmd>
<TargetRef>664583E90A71</TargetRef>
−
	<SourceRef>
http://192.168.1.70:88/sync/?sessionid=3514778038247113972
</SourceRef>
<Data>200</Data>
</Status>
−
	<Status>
<CmdID>3</CmdID>
<MsgRef>1</MsgRef>
<CmdRef>6</CmdRef>
<Cmd>Alert</Cmd>
<TargetRef>addressbook</TargetRef>
<SourceRef>./contacts</SourceRef>
<Data>200</Data>
−
	<Item>
−
	<Data>
−
	<Anchor>
<Next>20060829T154726Z</Next>
</Anchor>
</Data>
</Item>
</Status>
−
	<Sync>
<CmdID>4</CmdID>
−
	<Target>
<LocURI>./contacts</LocURI>
</Target>
−
	<Source>
<LocURI>addressbook</LocURI>
</Source>
</Sync>
<Final/>
</SyncBody>
</SyncML>

[luz]

Es könnte daran liegen, dass für Anchor des CmdID=3 der Namespace fehlt:

<Anchor xmlns='syncml:metinf'>

Das ist syntaktisch nicht in Ordnung, und verletzt die SyncML DTD.

Wahrscheinlich müsste das aber generell verbessert werden, weil Tags aus dem "meta"-Namespace an verschiedener Stelle vorkommen.