CardDav sync draining battery by continiously resyncing due to an error
asked 2020-06-30 10:04:08 +0300
HI there!
Since about 3 days, my phone has been extremely hot and drained its battery within 4-5 hours while idle on my Xperia X, while Android support was disabled. After some digging, it seemed that the buteo CardDav synchronisation plugin was almost continuously using up 1 full CPU core according to htop.
After following the steps at https://sailfishos.org/wiki/CalDAV_and_CardDAV_Community_Contributions#Sync_Logs it seems like the sync plugin is failing and almost immediately restarting. Some relevant log lines:
[W] unknown:0 - void Syncer::continueSync(const QList<QtContacts::QContact>&, const QList<QtContacts::QContact>&, const QList<QtContacts::QContact>&) no contact id specified for contact with guid "16:AB:/dav.php/addressbooks/chris/default/:e1a2f6de68b142ce9f810ce75cb157b9" from account 16
[W] unknown:0 - CardDAV sync finished with error: 0 purging state data for account: 16
[C] unknown:0 - CardDAV sync failed: 401 ""
[D] unknown:0 - Session finished: "carddav.Contacts-16" , status: 3
[D] unknown:0 - aStatus 3
[D] unknown:0 - ProfileManager::syncProfile( "carddav.Contacts-16" )
[D] unknown:0 - found a valid sync profile with the given name: "carddav.Contacts-16"
[D] unknown:0 - Synchronizer::getBackUpRestoreState
[D] unknown:0 - Trying to start next sync in queue. Profile: "carddav.Contacts-6" false
[D] unknown:0 - Synchronizer::getBackUpRestoreState
[D] unknown:0 - Starting sync with profile "carddav.Contacts-6"
[D] unknown:0 - Disable sync on change: false false
[D] unknown:0 - Process 6924 has been killed
...
[D] {IRRELEVANT DATA CUT}<d:response><d:href>/dav.php/addressbooks/chris/default/e1a2f6de68b142ce9f810ce75cb157b9.vcf</d:href><d:propstat><d:prop><d:getetag>"80e6ca1aa324c64ab25574f71e063c6d"</d:getetag><card:address-data>BEGIN:VCARD "
[D] unknown:0 - "VERSION:3.0 "
[D] unknown:0 - "PRODID:-//Sabre//Sabre VObject 4.3.0//EN "
[D] unknown:0 - "UID:e1a2f6de68b142ce9f810ce75cb157b9 "
[D] unknown:0 - "FN:{REDACTED} "
[D] unknown:0 - "N:{REDACTED};{REDACTED};;; "
[D] unknown:0 - "BDAY:{REDACTED} "
[D] unknown:0 - "TEL;TYPE=CELL:{REDACTED} "
[D] unknown:0 - "NOTE:IBAN:{REDACTED} "
[D] unknown:0 - "REV:20200425T111931Z "
[D] unknown:0 - "END:VCARD "
[D] unknown:0 - "</card:address-data></d:prop><d:status>HTTP/1.1 200 OK</d:status></d:propstat></d:response></d:multistatus>"
...
[D] unknown:0 - Parsed pure server-addition with guid: "16:AB:/dav.php/addressbooks/chris/default/:e1a2f6de68b142ce9f810ce75cb157b9"
[D] unknown:0 - void CardDav::downsyncComplete() downsync complete with total AMR: 63 , 0 , 0
...
[D] unknown:0 - contact: "16:AB:/dav.php/addressbooks/chris/default/:e1a2f6de68b142ce9f810ce75cb157b9" marked as added or modified remotely, not found locally
[D] unknown:0 - contact: "16:AB:/dav.php/addressbooks/chris/default/:e1a2f6de68b142ce9f810ce75cb157b9" was downloaded during a failed sync and then modified remotely
...
[W] unknown:0 - void Syncer::continueSync(const QList<QtContacts::QContact>&, const QList<QtContacts::QContact>&, const QList<QtContacts::QContact>&) no contact id specified for contact with guid "16:AB:/dav.php/addressbooks/chris/default/:e1a2f6de68b142ce9f810ce75cb157b9" from account 16
[W] unknown:0 - CardDAV sync finished with error: 0 purging state data for account: 16
[C] unknown:0 - CardDAV sync failed: 401 ""
[D] unknown:0 - New network state: true New type: "WLAN" ( 2 )
[D] unknown:0 - Session finished: "carddav.Contacts-16" , status: 3
[D] unknown:0 - aStatus 3
[D] unknown:0 - ProfileManager::syncProfile( "carddav.Contacts-16" )
[D] unknown:0 - found a valid sync profile with the given name: "carddav.Contacts-16"
[D] unknown:0 - Synchronizer::getBackUpRestoreState
[D] unknown:0 - Trying to start next sync in queue. Profile: "carddav.Contacts-6" false
[D] unknown:0 - Synchronizer::getBackUpRestoreState
[D] unknown:0 - Starting sync with profile "carddav.Contacts-6"
And the cycle starts anew.
Any hints on how to resolve this would be appreciated. I'm using Baikal 7.0 (which uses Sabre/Dav 4.1.0) as my CalDAV and CardDav server, if that matters. I guess I'll try duplicating the contact and removing the one that caused the synchronisation issue.
EDIT: Deleting and readding the contact via another device solved the problem!
And as a suggestion on the software side: it would be nice if the synchronisation daemon would disable the synchronisation if it fails for example 3 times in a row, while notifying the user with some helpful information why it went wrong, so they know about it and can take action.
Kind regards, Chris
Hello, may I ask how often did you setup the sync in the settings ? Twice a day, every hour ? It's strange that Buteo is restarting a failed attempt immediately. As far as I know, it should restart only at the next sync time.
Damien Caliste ( 2020-06-30 11:21:33 +0300 )editI've set it to sync once an hour. A part of the log mentioned the next synchronisation was scheduled in an hour, but in reality it started synchronising the failed contacts within a few seconds. I can attach a full log which was taken in about 15 minutes later this day if needed, but it contains a lot of personal information that I need to clean out and it's about 550 000 lines long and about 45MB in size!
I've had this problem since Sunday evening. Back then, I briefly turned on my internet to check the modified train schedule and then turned it back off. Could a connection loss be problematic if it happens during a synchronisation?
ahappyhuman ( 2020-06-30 11:39:28 +0300 )editOk, thanks for the details. Could you paste somewhere, just every lines from the CardDAV plugin error to the schedule of the next round, and then the lines at around the start of the plugin again ? These lines should not contains any personal data and would help to follow the logic in Buteo code.
I notice that you have several account enabled, so for the parts that you already posted, it's just that account 6 is starting syncing after account 16 (the failing one), not really that account 16 is restarted just after its failure. That being said, I trust your reasoning that the sync attempts are restarted too close together because of the battery drain, but I cannot figure why at the moment. My only guess is that the account 16 is going into an infinite loop, darining the battery and then killed by Buteo after it timed out. But if I remember well, the timeout is 30 minutes. I need to check. So with a one hour schedule, it should not restart immediately...
Damien Caliste ( 2020-06-30 11:47:41 +0300 )editThere is possibly a general problem lurking in the error handling.
I have recurring trouble with battery drainage in Flight mode: Power consumption sometimes goes UP (maybe 10x) when in Flight mode and back DOWN with radios enabled. This has killed my device (Xperia X) overnight a couple of times. While I haven't been able to track down the cause, I heavily suspect sync to be the culprit.
Since it is not immediately clear when this happens, I've resorted to rebooting every time I turn Flight mode on :(
So, maybe there is a race condition or something in the error handling in sync?
JooJ ( 2020-07-01 12:18:55 +0300 )edit@Damien Caliste I've pasted the logs over here: https://pastebin.com/0aZUn9FQ If you need more, I can provide more, but I really haven't found a comfortable way to delete about 10 000 lines at the same time :)
ahappyhuman ( 2020-07-02 01:07:45 +0300 )edit