Bug 82863 - Suspending sync is failing after PBAP transfer has finished.
Summary: Suspending sync is failing after PBAP transfer has finished.
Status: RESOLVED FIXED
Alias: None
Product: SyncEvolution
Classification: Unclassified
Component: PIM Manager (show other bugs)
Version: 1.3.99.3
Hardware: Other All
: medium minor
Assignee: Patrick Ohly
QA Contact:
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2014-08-20 11:40 UTC by Mateusz Polrola
Modified: 2014-09-15 15:01 UTC (History)
1 user (show)

See Also:
i915 platform:
i915 features:


Attachments
dbus-monitor profile output for all sync (35.62 KB, text/plain)
2014-08-21 07:16 UTC, Mateusz Polrola
Details
dbus-monitor profile output for incremental sync (43.74 KB, text/plain)
2014-08-21 07:16 UTC, Mateusz Polrola
Details
dbus-monitor output during incremental sync with SuspendSync error (421.34 KB, text/plain)
2014-08-21 07:17 UTC, Mateusz Polrola
Details
dbus-monitor output during all sync with SuspendSync error (364.00 KB, text/plain)
2014-08-21 07:17 UTC, Mateusz Polrola
Details

Description Mateusz Polrola 2014-08-20 11:40:23 UTC
During synchronization of PBAP peer, suspend sync is failing when PBAP transfer has finished, but sync is still ongoing. 
Additionally in case of incremental sync, failure of suspending sync in middle of process (right after finishing first PBAP transfer), will finish sync process without executing second phase of sync.

PIM Manager should be able to suspend sync operation successfully, even if PABP transfer has finished, not causing premature finish of sync.
Comment 1 Patrick Ohly 2014-08-20 15:29:22 UTC
(In reply to comment #0)
> During synchronization of PBAP peer, suspend sync is failing when PBAP
> transfer has finished, but sync is still ongoing.

Out of curiosity, how long does the sync keep running after the download has finished? The sync should finish shortly after the download, so the chance of hitting this time window should be small.

Is this perhaps with downloading in chunks enabled?

You mentioned seeing a NULL pointer access when analyzing this. Where in the source was that and/or what is the exact error when suspending fails?
Comment 2 Mateusz Polrola 2014-08-21 07:16:32 UTC
Created attachment 105006 [details]
dbus-monitor profile output for all sync
Comment 3 Mateusz Polrola 2014-08-21 07:16:57 UTC
Created attachment 105008 [details]
dbus-monitor profile output for incremental sync
Comment 4 Mateusz Polrola 2014-08-21 07:17:31 UTC
Created attachment 105010 [details]
dbus-monitor output during incremental sync with SuspendSync error
Comment 5 Mateusz Polrola 2014-08-21 07:17:50 UTC
Created attachment 105011 [details]
dbus-monitor output during all sync with SuspendSync error
Comment 6 Mateusz Polrola 2014-08-21 07:18:42 UTC
(In reply to comment #1)
> (In reply to comment #0)
> > During synchronization of PBAP peer, suspend sync is failing when PBAP
> > transfer has finished, but sync is still ongoing.
> 
> Out of curiosity, how long does the sync keep running after the download has
> finished? The sync should finish shortly after the download, so the chance
> of hitting this time window should be small.

Please find attached logs from dbus-monitor run in profile mode, during incremental and all sync - for incremental sync sync finished 1 second after transfer, for all sync it finished 4 seconds after transfer.

> Is this perhaps with downloading in chunks enabled?

No, download in chunks is not enabled.
 
> You mentioned seeing a NULL pointer access when analyzing this. Where in the
> source was that and/or what is the exact error when suspending fails?

You probably misunderstand me, there is no NULL pointer access, I've checked with Syncevolution code and saw that error message that I'm getting is coming from exception in PbapSession::setFreeze (attached dbus-monitor logs with error message, for both incremental and all sync).
Comment 7 Patrick Ohly 2014-08-21 14:13:16 UTC
(In reply to comment #6)
> (In reply to comment #1)
> > (In reply to comment #0)
> > > During synchronization of PBAP peer, suspend sync is failing when PBAP
> > > transfer has finished, but sync is still ongoing.
> > 
> > Out of curiosity, how long does the sync keep running after the download has
> > finished? The sync should finish shortly after the download, so the chance
> > of hitting this time window should be small.
> 
> Please find attached logs from dbus-monitor run in profile mode, during
> incremental and all sync - for incremental sync sync finished 1 second after
> transfer, for all sync it finished 4 seconds after transfer.
> 
> > Is this perhaps with downloading in chunks enabled?
> 
> No, download in chunks is not enabled.
>  
> > You mentioned seeing a NULL pointer access when analyzing this. Where in the
> > source was that and/or what is the exact error when suspending fails?
> 
> You probably misunderstand me, there is no NULL pointer access, I've checked
> with Syncevolution code and saw that error message that I'm getting is
> coming from exception in PbapSession::setFreeze (attached dbus-monitor logs
> with error message, for both incremental and all sync).

Indeed, from what you said I had expected an empty boost::shared_ptr reference (which leads to an exception); what the log shows is a race condition where obexd finishes and removes the transfer object at the same time as SyncEvolution sends a Suspend method call:

method call sender=:1.1 -> dest=org._01.pim.contacts serial=10 path=/org/01/pim/contacts; interface=org._01.pim.contacts.Manager; member=SuspendSync
   string "htc"
signal sender=:1.7 -> dest=(null destination) serial=25 path=/org/bluez/obex/client/session1/transfer1; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.bluez.obex.Transfer1"
   array [
      dict entry(
         string "Transferred"
         variant             uint64 285950
      )
   ]
   array [
   ]
...
signal sender=:1.7 -> dest=(null destination) serial=26 path=/org/bluez/obex/client/session1/transfer1; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.bluez.obex.Transfer1"
   array [
      dict entry(
         string "Status"
         variant             string "complete"
      )
   ]
   array [
   ]
signal sender=:1.7 -> dest=(null destination) serial=27 path=/; interface=org.freedesktop.DBus.ObjectManager; member=InterfacesRemoved
   object path "/org/bluez/obex/client/session1/transfer1"
   array [
      string "org.freedesktop.DBus.Properties"
      string "org.freedesktop.DBus.Introspectable"
      string "org.bluez.obex.Transfer1"
   ]
method call sender=:1.8 -> dest=org.bluez.obex serial=8 path=/org/bluez/obex/client/session1/transfer1; interface=org.bluez.obex.Transfer1; member=Suspend
error sender=:1.7 -> dest=:1.8 error_name=org.freedesktop.DBus.Error.UnknownObject reply_serial=8
   string "Method "Suspend" with signature "" on interface "org.bluez.obex.Transfer1" doesn't exist
"

The error string is a bit misleading, it's the object path which does not exist, not the interface. or method.

Anyway, SyncEvolution doesn't need to check the error. It knows that the transfer completed at the time when it receives the error, so it can simply ignore all errors.
Comment 8 Patrick Ohly 2014-08-27 07:27:54 UTC
Fixed in the following commit (not merged into master yet, commit hash will change):

commit a4ab216aff40aab6685f369dd13bb05993dbfd47
Author: Patrick Ohly <patrick.ohly@intel.com>
Date:   Tue Aug 26 17:03:23 2014 +0200

    PIM: handle SuspendPeer() before and after transfer (FDO #82863)
    
    A SuspendPeer() only succeeded while the underlying Bluetooth transfer
    was active. Outside of that, Bluez errors caused SyncEvolution to
    attempt a cancelation of the transfer and stopped the sync.
    
    When the transfer was still queueing, obexd returns
    org.bluez.obex.Error.NotInProgress. This is difficult to handle for
    SyncEvolution: it cannot prevent the transfer from starting and has to
    let it become active before it can suspend the transfer. Canceling
    would lead to difficult to handle error cases (like partially parsed
    data) and therefore is not done.
    
    The Bluez team was asked to implement suspending of queued transfers
    (see "org.bluez.obex.Transfer1 Suspend/Resume in queued state" on
    linux-bluetooth@vger.kernel.org), so this case might not happen
    anymore with future Bluez.
    
    When the transfer completes before obexd processes the Suspend(),
    org.freedesktop.DBus.Error.UnknownObject gets returned by
    obexd. SyncEvolution can ignore errors which occur after the active
    transfer completed. In addition, it should prevent starting the next
    one. This may be relevant for transfer in chunks, although the sync
    engine will also stop asking for data and thus typically no new
    transfer gets triggered anyway.

Also note that sync.py can now be used to test this:

commit 9423ffea53252350dc8c1c835f2e56107b6bef8b
Author: Patrick Ohly <patrick.ohly@intel.com>
Date:   Tue Aug 26 16:46:21 2014 +0200

    PIM: add suspend/resume/abort to sync.py
    
    CTRL-C while waiting for the end of a sync causes an interactive
    prompt to appear where one can choose been suspend/resume/abort and
    continuing to wait. CTRL-C again in the prompt aborts the script.

I was not able to come up with reliable automated testing for the different situations.
Comment 9 Patrick Ohly 2014-09-15 15:01:44 UTC
Merged into master, part of 1.4.99.4 (being released right now).


Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.