Google Account Contact Sync deletes and recreates contacts and uses high CPU

asked 2020-05-12 19:46:51 +0200

gabrielharrison
86 ●1 ●5 ●7

updated 2020-05-13 12:04:20 +0200

Hi,

When syncing contacts with a Google account the the contact list is deleted and recreated causing the process to get more and more CPU intensive on each synchonisation.

I initially had the issue with an account that had 640 contacts and the sqlite db in /home/nemo/.local/share/system/Contacts/qtcontacts-sqlite bloated to 150MB. I have recreated the issue with a clean database and a google account with one entry.

Device Used: - Sony Xperia 10 - Sailfish OS 3.3.0.16 Rokua - Android App Support Stopped - No contacts except Voicemail - PC with sqlitebrowser.org, WinSCP, Putty

Reproduction Steps:

1. Create a new google account
2. Add a single entry to the contacts with just First and Last Name
3. Enable developer mode on phone
4. Connect to phone with WinSCP and browse to /home/nemo/.local/share/system/Contacts/qtcontacts-sqlite
5. Delete contents of qtcontacts-sqlite folder
6. Restart phone
7. Stop Android (this was just to to be cautious)
8. Connect to phone with Putty and open start 'top'
9. Connect to phone with WinSCP and browse to /home/nemo/.local/share/system/Contacts/qtcontacts-sqlite
10. Copy content of qtcontacts-sqlite to PC, open with sqlitebrowser and confirm only entry in Contacts table is Voicemail
11. On phone add the new Google account with only Contacts enabled, two-way sync, sync content manually.
12. Use pulley menu to start a sync
13. Confirm in Putty that google-contacts and after a few seconds contactsd are at the top of 'top' using ~95% CPU
14. Wait until google-contacts and contactsd are no longer at the top of 'top'
15. In WinSCP copy the content of qtcontacts-sqlite to PC, open with sqlitebrowser and confirm two entries in Contacts table are Voicemail and new Google one
16. Make a note of the contactId value
17. Repeat steps 12 to 16.
18. In database do to DeletedContacts table and confirm there is an entry for the contactId previously noted
19. Repeat steps 12 to 16 again and confirm there is a new entry in the DeletedContacts table

Here is the journal output for a single sync.

May 12 16:57:06 Sailfish mce[1992]: modules/proximity.c: mp_datapipe_set_proximity_sensor_actual(): state: OPEN -> UNDEF
May 12 16:57:17 Sailfish google-signon-client[1035]: [W] unknown:0 - This device does not have a BT adapter
May 12 16:57:18 Sailfish invoker[5379]: SailfishKeyProvider_ini_read: reached end of file
May 12 16:57:18 Sailfish invoker[5379]: SailfishKeyProvider_ini_read: reached end of file
May 12 16:57:18 Sailfish onedrive-signon-client[1042]: [W] unknown:0 - This device does not have a BT adapter
May 12 16:57:19 Sailfish invoker[5379]: SailfishKeyProvider_ini_read: reached end of file
May 12 16:57:19 Sailfish invoker[5379]: SailfishKeyProvider_ini_read: reached end of file
May 12 16:57:19 Sailfish dbus-daemon[5298]: dbus-daemon[5298]: [session uid=100000 pid=5298] Activating service name='com.google.code.AccountsSSO.SingleSignOn' requested by ':1.282' (uid=100000 pid=1042 comm="/usr/lib/buteo-plugins-qt5//oopp/onedrive-signon-c" label="u:r:kernel:s0")
May 12 16:57:19 Sailfish dbus-daemon[5298]: dbus-daemon[5298]: [session uid=100000 pid=5298] Successfully activated service 'com.google.code.AccountsSSO.SingleSignOn'
May 12 16:57:19 Sailfish syncemail-client[1050]: [W] unknown:0 - This device does not have a BT adapter
May 12 16:57:20 Sailfish syncemail-client[1050]: [D] unknown:0 - Messaging :  opening database
May 12 16:57:20 Sailfish syncemail-client[1050]: [D] unknown:0 - void SyncEmailClient::triggerSync() Starting scheduled sync for email account:  15
May 12 16:57:20 Sailfish syncemail-client[1050]: [W] unknown:0 - QSharedPointer<Accounts::Account> QMailStorePrivate::getEmailAccount(Accounts::AccountId) E-mail Services not found, make sure that *.service and *.provider files are properly installed and e-mail services are enabled.
May 12 16:57:20 Sailfish syncemail-client[1050]: [W] unknown:0 - 1050 Unable to account
May 12 16:57:20 Sailfish syncemail-client[1050]: [W] unknown:0 - Email account has no inbox.
May 12 16:57:20 Sailfish syncemail-client[1050]: [W] unknown:0 - void EmailAgent::activityChanged(QMailServiceAction::Activity) operation failed error code: 1025 error text: "Account disabled\n[Framework error occurred.]" account: 15 connection status: 0 sender: QMailRetrievalAction(0x1c52280)
May 12 16:57:20 Sailfish twitter-posts-client[1064]: [W] unknown:0 - This device does not have a BT adapter
May 12 16:57:21 Sailfish invoker[5379]: SailfishKeyProvider_ini_read: reached end of file
May 12 16:57:21 Sailfish invoker[5379]: SailfishKeyProvider_ini_read: reached end of file
May 12 16:57:21 Sailfish twitter-notifications-client[1088]: [W] unknown:0 - This device does not have a BT adapter
May 12 16:57:22 Sailfish estart[5898]: [W] unknown:0 - writeProfileFile() called, forcing disk write: "/home/nemo/.cache/msyncd/sync/syncemail-15.xml"
May 12 16:57:22 Sailfish [5364]: [W] unknown:0 - writeProfileFile() called, forcing disk write: "/home/nemo/.cache/msyncd/sync/syncemail-15.xml"
May 12 16:57:22 Sailfish estart[5898]: [W] unknown:0 - writeProfileFile() called, forcing disk write: "/home/nemo/.cache/msyncd/sync/google.Signon-15.xml"
May 12 16:57:22 Sailfish google-signon-client[1117]: [W] unknown:0 - This device does not have a BT adapter
May 12 16:57:23 Sailfish invoker[5379]: SailfishKeyProvider_ini_read: reached end of file
May 12 16:57:23 Sailfish invoker[5379]: SailfishKeyProvider_ini_read: reached end of file
May 12 16:57:23 Sailfish syncemail-client[1132]: [W] unknown:0 - This device does not have a BT adapter
May 12 16:57:24 Sailfish invoker[5379]: SailfishKeyProvider_ini_read: reached end of file
May 12 16:57:24 Sailfish invoker[5379]: SailfishKeyProvider_ini_read: reached end of file
May 12 16:57:24 Sailfish twitter-posts-client[1064]: [W] unknown:0 - Queued images being saved: 0
May 12 16:57:24 Sailfish [5364]: [W] unknown:0 - writeProfileFile() called, forcing disk write: "/home/nemo/.cache/msyncd/sync/google.Signon-15.xml"
May 12 16:57:24 Sailfish estart[5898]: [W] unknown:0 - writeProfileFile() called, forcing disk write: "/home/nemo/.cache/msyncd/sync/google.Contacts-15.xml"
May 12 16:57:24 Sailfish syncemail-client[1132]: [D] unknown:0 - Messaging :  opening database
May 12 16:57:24 Sailfish syncemail-client[1132]: [D] unknown:0 - void SyncEmailClient::triggerSync() Starting scheduled sync for email account:  14
May 12 16:57:25 Sailfish [5364]: [W] unknown:0 - writeProfileFile() called, forcing disk write: "/home/nemo/.cache/msyncd/sync/google.Contacts-15.xml"
May 12 16:57:25 Sailfish estart[5898]: [W] unknown:0 - writeProfileFile() called, forcing disk write: "/home/nemo/.cache/msyncd/sync/google.Calendars-15.xml"
May 12 16:57:25 Sailfish [5364]: [W] unknown:0 - writeProfileFile() called, forcing disk write: "/home/nemo/.cache/msyncd/sync/google.Calendars-15.xml"
May 12 16:57:25 Sailfish google-signon-client[1117]: [D] unknown:0 - account-service.cpp: 169 onChanged
May 12 16:57:25 Sailfish estart[5898]: [D] unknown:0 - account.cpp: 626 account_store_cb Saved accunt ID: 15
May 12 16:57:25 Sailfish lipstick[5572]: [W] unknown:0 - AbstractImageDownloader::about to fetch image: "https://pbs.twimg.com/media/EX1DMOKXkAMIL1f.jpg"
May 12 16:57:25 Sailfish estart[5898]: [W] unknown:0 - QSharedPointer<Accounts::Account> QMailStorePrivate::getEmailAccount(Accounts::AccountId) E-mail Services not found, make sure that *.service and *.provider files are properly installed and e-mail services are enabled.
May 12 16:57:25 Sailfish estart[5898]: [W] unknown:0 - 5898 Unable to account
May 12 16:57:25 Sailfish estart[5898]: [W] unknown:0 - Email account has no inbox.
May 12 16:57:25 Sailfish lipstick[5572]: [W] unknown:0 - void AbstractImageDownloader::queue(const QString&, const QVariantMap&) duplicate running request, appending metadata.
May 12 16:57:25 Sailfish lipstick[5572]: [W] unknown:0 - void AbstractImageDownloader::queue(const QString&, const QVariantMap&) duplicate running request, appending metadata.
May 12 16:57:25 Sailfish lipstick[5572]: [W] unknown:0 - AbstractImageDownloader::about to fetch image: "http://pbs.twimg.com/profile_images/421329005543821313/IZgz048D_bigger.png"
May 12 16:57:25 Sailfish lipstick[5572]: [W] unknown:0 - void AbstractImageDownloader::queue(const QString&, const QVariantMap&) duplicate running request, appending metadata.
May 12 16:57:25 Sailfish onedrive-signon-client[1042]: [D] unknown:0 - account-service.cpp: 169 onChanged
May 12 16:57:25 Sailfish [5506]: [D] unknown:0 - account.cpp: 626 account_store_cb Saved accunt ID: 12
May 12 16:57:25 Sailfish [5506]: [W] unknown:0 - "jolla-signon-ui: CredentialsNeedUpdate now false.  From: .  Notification currently exists: false"
May 12 16:57:25 Sailfish onedrive-signon-client[1042]: [D] unknown:0 - account-service.cpp: 169 onChanged
May 12 16:57:25 Sailfish syncemail-client[1132]: [W] unknown:0 - void EmailAgent::activityChanged(QMailServiceAction::Activity) operation failed error code: 1034 error text: "Unable to export updates for unconfigured account" account: 0 connection status: 0 sender: QMailRetrievalAction(0x390e58)
May 12 16:57:25 Sailfish google-contacts-client[1154]: [W] unknown:0 - This device does not have a BT adapter
May 12 16:57:26 Sailfish google-contacts-client[1154]: [W] unknown:0 - The 'mergePresenceChanges' option has not been configured - presence changes will only be reported via ContactManagerEngine::contactsPresenceChanged()
May 12 16:57:26 Sailfish invoker[5379]: SailfishKeyProvider_ini_read: reached end of file
May 12 16:57:26 Sailfish invoker[5379]: SailfishKeyProvider_ini_read: reached end of file
May 12 16:57:27 Sailfish dbus-daemon[5298]: dbus-daemon[5298]: [session uid=100000 pid=5298] Activating service name='org.nemomobile.calendardataservice' requested by ':1.29' (uid=100000 pid=5572 comm="/usr/bin/lipstick -plugin evdevtouch -plugin evdev" label="u:r:kernel:s0")
May 12 16:57:27 Sailfish dbus-daemon[5298]: dbus-daemon[5298]: [session uid=100000 pid=5298] Successfully activated service 'org.nemomobile.calendardataservice'
May 12 16:57:27 Sailfish calendardataservice[1186]: [D] unknown:0 - Messaging :  opening database
May 12 16:57:27 Sailfish calendardataser[1186]: Unable to load account 9
May 12 16:57:27 Sailfish calendardataservice[1186]: [W] unknown:0 - QSharedPointer<Accounts::Account> QMailStorePrivate::getEmailAccount(Accounts::AccountId) Account with was not found
May 12 16:57:27 Sailfish calendardataservice[1186]: [W] unknown:0 - Accounts: "Account 9 not found in DB"
May 12 16:57:27 Sailfish calendardataservice[1186]: [W] unknown:0 - 1186 Unable to account
May 12 16:57:27 Sailfish calendardataservice[1186]: [W] unknown:0 - Default plugin: invalid email account "9"
May 12 16:57:27 Sailfish calendardataservice[1186]: [W] unknown:0 - Notebook "bef9dca7-fa57-4fab-965a-415d2ad3f50a" do not have a valid account email address
May 12 16:57:27 Sailfish calendardataservice[1186]: [W] unknown:0 - Default account was not found!
May 12 16:57:27 Sailfish calendardataser[1186]: Unable to load account 9
May 12 16:57:27 Sailfish calendardataser[1186]: Unable to load account 9
May 12 16:57:27 Sailfish calendardataservice[1186]: [C] unknown:0 - QString EasInvitationPlugin::emailAddress(const QString&) Cannot allocate account object
May 12 16:57:27 Sailfish calendardataser[1186]: Unable to load account 9
May 12 16:57:27 Sailfish calendardataser[1186]: Unable to load account 9
May 12 16:57:27 Sailfish calendardataservice[1186]: [C] unknown:0 - QString EasInvitationPlugin::emailAddress(const QString&) Cannot allocate account object
May 12 16:57:27 Sailfish calendardataser[1186]: Unable to load account 9
May 12 16:57:27 Sailfish calendardataservice[1186]: [W] unknown:0 - QSharedPointer<Accounts::Account> QMailStorePrivate::getEmailAccount(Accounts::AccountId) E-mail Services not found, make sure that *.service and *.provider files are properly installed and e-mail services are enabled.
May 12 16:57:27 Sailfish calendardataservice[1186]: [W] unknown:0 - 1186 Unable to account
May 12 16:57:27 Sailfish calendardataservice[1186]: [W] unknown:0 - Default plugin: invalid email account "15"
May 12 16:57:27 Sailfish calendardataservice[1186]: [W] unknown:0 - Notebook "668b409e-3006-42da-939c-47b51a245345" do not have a valid account email address
May 12 16:57:27 Sailfish calendardataservice[1186]: [W] unknown:0 - No transactionId, discarding results
May 12 16:57:28 Sailfish calendardataser[1186]: Unable to load account 9
May 12 16:57:28 Sailfish calendardataservice[1186]: [C] unknown:0 - QString EasInvitationPlugin::emailAddress(const QString&) Cannot allocate account object
May 12 16:57:28 Sailfish calendardataser[1186]: Unable to load account 9
May 12 16:57:28 Sailfish calendardataser[1186]: Unable to load account 9
May 12 16:57:28 Sailfish calendardataservice[1186]: [C] unknown:0 - QString EasInvitationPlugin::emailAddress(const QString&) Cannot allocate account object
May 12 16:57:28 Sailfish calendardataser[1186]: Unable to load account 9
May 12 16:57:28 Sailfish calendardataser[1186]: Unable to load account 9
May 12 16:57:28 Sailfish calendardataservice[1186]: [C] unknown:0 - QString EasInvitationPlugin::emailAddress(const QString&) Cannot allocate account object
May 12 16:57:28 Sailfish calendardataser[1186]: Unable to load account 9
May 12 16:57:28 Sailfish calendardataservice[1186]: [W] unknown:0 - QSharedPointer<Accounts::Account> QMailStorePrivate::getEmailAccount(Accounts::AccountId) E-mail Services not found, make sure that *.service and *.provider files are properly installed and e-mail services are enabled.
May 12 16:57:28 Sailfish calendardataservice[1186]: [W] unknown:0 - 1186 Unable to account
May 12 16:57:28 Sailfish calendardataservice[1186]: [W] unknown:0 - Default plugin: invalid email account "15"
May 12 16:57:28 Sailfish calendardataservice[1186]: [W] unknown:0 - Notebook "668b409e-3006-42da-939c-47b51a245345" do not have a valid account email address
May 12 16:57:28 Sailfish calendardataservice[1186]: [W] unknown:0 - No transactionId, discarding results
May 12 16:57:28 Sailfish calendardataservice[1186]: [W] unknown:0 - No transactionId, discarding results
May 12 16:57:28 Sailfish google-signon-client[1117]: [D] unknown:0 - account-service.cpp: 169 onChanged
May 12 16:57:28 Sailfish [5506]: [D] unknown:0 - account.cpp: 626 account_store_cb Saved accunt ID: 15
May 12 16:57:28 Sailfish [5506]: [W] unknown:0 - "jolla-signon-ui: CredentialsNeedUpdate now false.  From: .  Notification currently exists: false"
May 12 16:57:28 Sailfish google-signon-client[1117]: [D] unknown:0 - account-service.cpp: 169 onChanged
May 12 16:57:29 Sailfish healthd: battery l=52 v=3846 t=27.0 h=2 st=2 c=-21 chg=u
May 12 16:57:29 Sailfish dbus-daemon[5298]: invoker: Invoking execution: '/usr/bin/signond'
May 12 16:57:34 Sailfish udhcpd[3700]: udhcpd: sending ACK to 192.168.2.6
May 12 16:57:36 Sailfish [5861]: [W] unknown:0 - CDExport: triggering contacts remote sync: ""
May 12 16:57:51 Sailfish mce[1992]: modules/display.c: mdy_display_state_enter(): current display state = DIM
May 12 16:57:54 Sailfish mce[1992]: modules/display.c: mdy_display_state_leave(): current display state = POWER_DOWN
May 12 16:57:54 Sailfish sensorfwd[3062]: virtual bool HybrisAdaptor::setInterval(unsigned int, int) setInterval not ok
May 12 16:57:54 Sailfish lipstick[5572]: [D] unknown:0 - sleepDisplay
May 12 16:57:54 Sailfish kernel: dsi_panel_driver_touch_pinctrl_set_state: invalid 'sde_touch_suspend' pinstate
May 12 16:57:54 Sailfish kernel: @@@@ panel power off @@@@
May 12 16:57:54 Sailfish mce[1992]: modules/display.c: mdy_display_state_enter(): current display state = OFF
May 12 16:57:54 Sailfish mce[1992]: modules/proximity.c: mp_datapipe_set_proximity_sensor_actual(): state: UNDEF -> OPEN
May 12 16:57:55 Sailfish syncemail-client[1349]: [W] unknown:0 - This device does not have a BT adapter
May 12 16:57:56 Sailfish lipstick[5572]: [W] unknown:0 - Queued images being saved: 2
May 12 16:57:56 Sailfish syncemail-client[1349]: [D] unknown:0 - Messaging :  opening database
May 12 16:57:56 Sailfish syncemail-client[1349]: [D] unknown:0 - void SyncEmailClient::triggerSync() Starting scheduled sync for email account:  15
May 12 16:57:56 Sailfish syncemail-client[1349]: [W] unknown:0 - QSharedPointer<Accounts::Account> QMailStorePrivate::getEmailAccount(Accounts::AccountId) E-mail Services not found, make sure that *.service and *.provider files are properly installed and e-mail services are enabled.
May 12 16:57:56 Sailfish syncemail-client[1349]: [W] unknown:0 - 1349 Unable to account
May 12 16:57:56 Sailfish syncemail-client[1349]: [W] unknown:0 - Email account has no inbox.
May 12 16:57:56 Sailfish syncemail-client[1349]: [W] unknown:0 - void EmailAgent::activityChanged(QMailServiceAction::Activity) operation failed error code: 1025 error text: "Account disabled\n[Framework error occurred.]" account: 15 connection status: 0 sender: QMailRetrievalAction(0xe693f0)
May 12 16:58:00 Sailfish [32248]: QObject::disconnect: Unexpected null parameter
May 12 16:58:00 Sailfish [32248]: QObject::disconnect: Unexpected null parameter
May 12 16:58:00 Sailfish [32248]: QObject::disconnect: Unexpected null parameter
May 12 16:58:00 Sailfish [32248]: QObject::disconnect: Unexpected null parameter
May 12 16:58:00 Sailfish [32248]: QObject::disconnect: Unexpected null parameter
May 12 16:58:00 Sailfish [32248]: QObject::disconnect: Unexpected null parameter
May 12 16:58:00 Sailfish [32248]: QObject::disconnect: Unexpected null parameter
May 12 16:58:00 Sailfish [32248]: QObject::disconnect: Unexpected null parameter
May 12 16:58:00 Sailfish [32248]: QObject::disconnect: Unexpected null parameter
May 12 16:58:00 Sailfish [32248]: QObject::disconnect: Unexpected null parameter
May 12 16:58:00 Sailfish [32248]: QObject::disconnect: Unexpected null parameter
May 12 16:58:00 Sailfish [32248]: QObject::disconnect: Unexpected null parameter
May 12 16:58:00 Sailfish [32248]: QObject::disconnect: Unexpected null parameter
May 12 16:58:00 Sailfish [32248]: QObject::disconnect: Unexpected null parameter
May 12 16:58:00 Sailfish [32248]: QObject::disconnect: Unexpected null parameter
May 12 16:58:00 Sailfish [32248]: QObject::disconnect: Unexpected null parameter
May 12 16:58:00 Sailfish [32248]: QObject::disconnect: Unexpected null parameter
May 12 16:58:02 Sailfish mce[1992]: modules/proximity.c: mp_datapipe_set_proximity_sensor_actual(): state: OPEN -> UNDEF
May 12 16:58:21 Sailfish [5861]: [W] unknown:0 - CDExport: exporting changes: 1 0 1
May 12 16:58:22 Sailfish google-contacts-client[1454]: [W] unknown:0 - This device does not have a BT adapter
May 12 16:58:23 Sailfish google-contacts-client[1454]: [W] unknown:0 - The 'mergePresenceChanges' option has not been configured - presence changes will only be reported via ContactManagerEngine::contactsPresenceChanged()
May 12 16:58:23 Sailfish invoker[5379]: SailfishKeyProvider_ini_read: reached end of file
May 12 16:58:23 Sailfish invoker[5379]: SailfishKeyProvider_ini_read: reached end of file
May 12 16:58:29 Sailfish healthd: battery l=52 v=3873 t=27.0 h=2 st=2 c=-277 chg=u
May 12 16:58:37 Sailfish kernel: R0: [cds_mc_thread][70883452970] [16:58:37.477064]  wlan: [5235:W :PE ] lim_process_probe_rsp_frame: 217: Recved Probe Resp from AP,AP-alive

With a bigger address book of 640 entries, automatic syncing (every 4-5 minutes?) and Android having access to the contacts this slowly made my phone grind to a halt. The sync 11500 deleted rows in about 1 hour 15 minutes.

Gabriel

EDIT1: With Android enabled and my usual 640 contacts, two more processes sit at 90% to 100% CPU, d.process.acore and apkd-bridge. Process apkd-bridge is high for about 20 seconds but contactsd takes 2 minutes 55 seconds and d.process.acore 4 minutes 5 seconds. With syncing set to automatic the next sync start almost immediately!