Hello Patrick,
> It seems to me that the client gets confused here. If it cannot suspend,
> it should simply complete the session.
I agree with your diagnosis - if it is too late for a client to suspend it
should terminate the session normally, and not do the kind of abort the log
shows here.
There's IMHO one reason for "too late" - if the client is about to send the
last message (final message of map phase), it does not make sense to request a
suspend.
>From the log snippets alone I can't see if it's really that case, but I guess
>so. Do you have complete HTML logs of this test case?
Most probably, there should be an extra check for that "too late" suspend.
> I'm a bit unsure about how to call SessionStep() after asking for a
> suspend. I think we observed that it was waiting for the server reply,
> so we call it with GOTDATA. The sequence is this ("before" is what is
> passed to the function, "after" what it sets):
STEPCMD_SUSPEND is an "out of order" step, and can be issued anywhere in
between. It always returns STEPCMD_OK. After issuing a STEPCMD_SUSPEND, you
should continue stepping exactly as if the STEPCMD_SUSPEND had never happened.
There's a note on this in engine_defs.h:249, but probably also should be
mentioned in the SDK docs.
Best Regards,
Lukas
On Feb 26, 2010, at 14:58 , Patrick Ohly wrote:
> Hello!
>
> I'm testing suspend/resume between SyncEvolution as client and as
> server. Our test suite contains a test which runs different sync
> scenarios and asks to suspend on the client side before processing each
> server reply, at all those positions (before first reply, second, etc.).
>
> I notice that it fails when the client suspends before processing the
> second-to-last server reply (in other words, before the final message
> from the client to the server).
>
> I'm attaching that client log. What I see is this (initial messages from
> SyncEvolution):
>
> * [2010-02-26 13:56:21.885] UserSuspendInjector: user suspend
> after getting reply #2
> * [2010-02-26 13:56:21.885] suspending before SessionStep() in
> STEPCMD_GOTDATA as requested by user
> * [2010-02-26 13:56:21.885] --------------- Ignoring all commands in
> this message (after 1 sec. request processing, 1 sec. total) with
> Status 514 (0=none) from here on
> * [2010-02-26 13:56:21.885] WARNING: Session locally flagged for
> suspend, reason=20032
> * [2010-02-26 13:56:21.885] suspending before SessionStep() in
> STEPCMD_GOTDATA as requested by user
> * [2010-02-26 13:56:21.885] engine already notified of suspend
> request, reverting to STEPCMD_GOTDATA
> ...
> * [2010-02-26 13:56:21.888] Outgoing WBXML message msgID=4 saved as XML
> translation
> ...
> * [2010-02-26 13:56:21.889] Warning: Failed with status code=0,
> statistics are incomplete!!
> ...
> * [2010-02-26 13:56:21.889] Session not any more in progress:
> NextMessage() returns OK status=0
> * [2010-02-26 13:56:21.889] forgetChangeLog: DISCARDING already loaded
> changelog with 7 entries
> * [2010-02-26 13:56:21.890] DeleteContext
> * [2010-02-26 13:56:21.890] TSyncSession::TerminateSession: calling
> InternalResetSession
> * [2010-02-26 13:56:21.890] Never received status for command
> 'SyncHdr', (outgoing MsgID=4, CmdID=0)
> * [2010-02-26 13:56:21.890] Deleted command 'SyncHdr' (outgoing
> MsgID=4, CmdID=0)
>
> That last outgoing message is also attached. It does *not* contain a
> request to suspend, but the client seems to think that is has suspended.
> It does not save its anchors. The server sees that last message and
> completes its session normally, saving the next client anchor. In the
> following session, the client anchor mismatch forces a slow sync.
>
> It seems to me that the client gets confused here. If it cannot suspend,
> it should simply complete the session.
>
> I'm a bit unsure about how to call SessionStep() after asking for a
> suspend. I think we observed that it was waiting for the server reply,
> so we call it with GOTDATA. The sequence is this ("before" is what is
> passed to the function, "after" what it sets):
>
> * [2010-02-26 14:51:26.073] after SessionStep: STEPCMD_NEEDDATA
> * [2010-02-26 14:51:26.073] UserSuspendInjector: user suspend after
> getting reply #2
> * [2010-02-26 14:51:26.073] suspending before SessionStep() in
> STEPCMD_GOTDATA as requested by user
> * [2010-02-26 14:51:26.073] before SessionStep: STEPCMD_SUSPEND
> * [2010-02-26 14:51:26.073] --------------- Ignoring all commands in
> this message (after 1 sec. request processing, 1 sec. total) with
> Status 514 (0=none) from here on
> * [2010-02-26 14:51:26.073] WARNING: Session locally flagged for
> suspend, reason=20032
> * [2010-02-26 14:51:26.073] after SessionStep: STEPCMD_OK
> * [2010-02-26 14:51:26.073] suspending before SessionStep() in
> STEPCMD_GOTDATA as requested by user
> * [2010-02-26 14:51:26.074] engine already notified of suspend
> request, reverting to STEPCMD_GOTDATA
> * [2010-02-26 14:51:26.074] before SessionStep: STEPCMD_GOTDATA
> * [2010-02-26 14:51:26.074] after SessionStep: STEPCMD_OK
> * [2010-02-26 14:51:26.074] before SessionStep: STEPCMD_STEP
> * [2010-02-26 14:51:26.074] after SessionStep: STEPCMD_PROGRESS
> * [2010-02-26 14:51:26.074] before SessionStep: STEPCMD_STEP
> * [2010-02-26 14:51:26.074] after SessionStep: STEPCMD_OK
> * [2010-02-26 14:51:26.074] before SessionStep: STEPCMD_STEP
> * [2010-02-26 14:51:26.074] Calling smlProcessData(NEXT_COMMAND)
> ...
>
> For the record, to reproduce the problem, set up "client-test" against a
> Synthesis server and run:
> CLIENT_TEST_SERVER=syncevolution CLIENT_TEST_RETRY=t
> CLIENT_TEST_RESEND=t CLIENT_TEST_SUSPEND=t CLIENT_TEST_INTERRUPT_AT=2
> CLIENT_TEST_EVOLUTION_PREFIX=file:///tmp/test_ ./client-test
> Client::Sync::file_vcard30::Suspend::testUserSuspendClientAdd
> ...
> Test name: Client::Sync::file_vcard30::Suspend::testUserSuspendClientAdd
> equality assertion failed
> - Expected: no error (remote, status 0)
> - Actual : unexpected slow sync (local, status 22000)
>
> --
> Best Regards, Patrick Ohly
>
> The content of this message is my personal opinion only and although
> I am an employee of Intel, the statements I make here in no way
> represent Intel's position on the issue, nor am I authorized to speak
> on behalf of Intel on this matter.
>
> <syncevolution-log.html><syncevolution-log_trm004_007_outgoing.xml>_______________________________________________
> os-libsynthesis mailing list
> os-libsynthesis@synthesis.ch
> http://lists.synthesis.ch/mailman/listinfo/os-libsynthesis
Lukas Zeller (l...@synthesis.ch)
-
Synthesis AG, SyncML Solutions & Sustainable Software Concepts
i...@synthesis.ch, http://www.synthesis.ch
_______________________________________________
os-libsynthesis mailing list
os-libsynthesis@synthesis.ch
http://lists.synthesis.ch/mailman/listinfo/os-libsynthesis
