[SyncEvolution] Help needed

[Patrick Ohly]

On Mon, 2016-02-29 at 01:34 +0100, deloptes wrote:
> Thanks for finding time for that as well. Appreciated!
> 
> Patrick Ohly wrote:
> 
> > On Sat, 2016-02-20 at 13:32 +0100, deloptes wrote:
> >> Hi Patrick, all,
> >> 
> >> a stupid shortcut activation got the previous mail sent incomplete.
> >> 
> >> So in the LocalTransportAgent
> >> 
> >> we have
> >> 
> >>             while (! m_reportSent  && m_parent && s.getState() ==
> >> SuspendFlags::NORMAL ) {
> >>                step("waiting for parent's ACK for sync report");
> >>             }
> >> 
> >> which never completes.
> > 
> > Yes, that's where the "waiting for parent's ACK for sync report" comes
> > from that we've seen earlier in a stack backtrace.
> > 
> 
> Right before the loop it says
> m_parent->m_storeSyncReport.start(report,                                             
> boost::bind(&LocalTransportAgentChild::syncReportReceived, this, _1));
> 
> but I do not see "sending sync report to parent" in the log
> It looks like it never gets called or something else, so m_reportSent stays
> false and the loop never ends. I am afraid I was wrong about this previous
> time , or perhaps confused.

Does the parent receive the sync report? There should be a "got child
sync report" message from LocalTransportAgent::storeSyncReport().

This looks like a low-level D-Bus communication problem between child
and parent. Why that happens is a complete mystery.

Did you compile with glib dbus or libdbus? Probably glib dbus, it is the
default. Then you can enable additional debug output for that internal
D-Bus communication with:
G_DBUS_DEBUG=call,return,payload

Always combine that with SYNCEVOLUTION_DEBUG=1.

Watch out for a method-call to "StoreSyncReport". It should appear
twice: once when getting send by the child, once when received by the
parent. For that message, a corresponding method-return message should
be sent by parent to child, again being logged twice.

This return message should trigger the
LocalTransportAgentChild::syncReportReceived callback.

> After I terminate I do not see this in the logs. I see "waiting for parent's
> ACK for sync report" only in the backtrace.
> I also do not see "child sending sync report" in the log.
> 
> Do you mean I should upload/attach some log (the html ones?)

I meant the text output from "SYNCEVOLUTION_DEBUG=1 syncevolution
--daemon=no loglevel=10 ..." - the one which has the SE_LOG_DEBUG()
output.

> > Which close() function?
> > 
> 
> I mean "TrackingSyncSource::close()" implemented in the plugin. 
> 
> If I understand correctly I should put there the logic for saving changes.
> In open() I set the resource/database and request a ticket, which would
> close saving all changes if only close() would have been called.
> In the log/dbg I see open finishing but no trace of close().
> This could be related to the above problem as well, but please confirm that
> I understand the usage properly.

You are right. However, close() is typically called very late. It might
be better to ensure earlier that requested changes really get written
persistently. There's a TrackingSyncSource::flush() method for that.

    /**
     * optional: write all changes, throw error if that fails
     *
     * This is called while the sync is still active whereas
     * close() is called afterwards. Reporting problems
     * as early as possible may be useful at some point,
     * but currently doesn't make a relevant difference.
     */
    virtual void flush() {}
    
    /**
     * closes the data source so that it can be reopened
     *
     * Just as open() it should not affect the state of
     * the database unless some previous action requires
     * it.
     */
    virtual void close() = 0;

-- 
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.