Sync stopped working, nothing to go by in terms of debugging



  • Hey @rfc2822, thanks for your response. I have now run setprop log.tag.davdroid VERBOSE and subsequently captured a logcat from the time I press "sync" to the time the "Synchronizing now" message disappears:

    11-23 09:22:44.435  3352  4808 W libutils.threads: Thread (this=0xf4334730): don't call waitForExit() from this Thread object's thread. It's a guaranteed deadlock!
    11-23 09:22:44.547  3675  3873 D InputReader: Input event(3): value=1 when=38895616080000
    11-23 09:22:44.547  3675  3873 D InputReader: Input event(3): value=1 when=38895616080000
    11-23 09:22:44.548  3675  3873 I InputReader: Touch event's action is 0x0 (deviceType=0) [pCnt=1, s=0.1210 ] when=38895616080000
    11-23 09:22:44.548  3675  3872 I InputDispatcher: Delivering touch to (4140): action: 0x4, toolType: 1
    11-23 09:22:44.549  3675  3872 I InputDispatcher: Delivering touch to (22371): action: 0x0, toolType: 1
    11-23 09:22:44.549 22371 22371 D ViewRootImpl@c18531c[AccountActivity]: ViewPostIme pointer 0
    11-23 09:22:44.630  3675  3873 D InputReader: Input event(3): value=0 when=38895698534000
    11-23 09:22:44.630  3675  3873 D InputReader: Input event(3): value=0 when=38895698534000
    11-23 09:22:44.630  3675  3873 I InputReader: Touch event's action is 0x1 (deviceType=0) [pCnt=1, s=] when=38895698534000
    11-23 09:22:44.630  3675  3872 I InputDispatcher: Delivering touch to (22371): action: 0x1, toolType: 1
    11-23 09:22:44.631 22371 22371 D ViewRootImpl@c18531c[AccountActivity]: ViewPostIme pointer 1
    11-23 09:22:44.646  3675  7035 V AudioService: AudioService playSoundEffect Type : 0, volume : -1.0
    11-23 09:22:44.646  3675  3955 V AudioService: received MSG_PLAY_SOUND_EFFECT onPlaySoundEffect start
    11-23 09:22:44.647  3352  3352 V APM_AudioPolicyManager: getAudioPolicyConfig: situation=1;device=0
    11-23 09:22:44.647  3352  3352 I APM_AudioPolicyManager: getSituationVolume: isBTConnected:0 isHeadConnected:0
    11-23 09:22:44.647  3352  3352 V APM_AudioPolicyManager: deviceInt = 0, situationInt = 1, situationVolume = 1.000000
    11-23 09:22:44.648  3352  3352 V APM_AudioPolicyManager: getOutput() device 2, stream 1, samplingRate 0, format 0, channelMask 3, flags 0
    11-23 09:22:44.648  3352  3352 V APM_AudioPolicyManager: selectOutput() commonFlags for output 13, 0000
    11-23 09:22:44.648  3352  3352 V APM_AudioPolicyManager: selectOutput() commonFlags for output 21, 0000
    11-23 09:22:44.648  3352  3352 V APM_AudioPolicyManager:   getOutputForDevice() returns output 13
    11-23 09:22:44.649  3352  3352 V APM_AudioPolicyManager: getOutput() device 2, stream 1, samplingRate 0, format 0, channelMask 3, flags 0
    11-23 09:22:44.649  3352  3352 V APM_AudioPolicyManager: selectOutput() commonFlags for output 13, 0000
    11-23 09:22:44.649  3352  3352 V APM_AudioPolicyManager: selectOutput() commonFlags for output 21, 0000
    11-23 09:22:44.649  3352  3352 V APM_AudioPolicyManager:   getOutputForDevice() returns output 13
    11-23 09:22:44.649  3675  3753 D ConnectivityService: filterNetworkStateForUid() uid: 1000 networkInfo: [type: WIFI[] - WIFI, state: CONNECTED/CONNECTED, reason: (unspecified), extra: "catalyst-guest", failover: false, available: true, roaming: false, metered: false]
    11-23 09:22:44.650  3352  3352 W AudioPolicyIntefaceImpl: Skipped to add effects on session 17
    11-23 09:22:44.650  3352  3352 V APM_AudioPolicyManager: startOutput() output 21, stream 1, session 17
    11-23 09:22:44.650  3352  3352 V APM_AudioPolicyManager: setBeaconMute(1) mBeaconMuteRefCount=1 mBeaconPlayingRefCount=0
    11-23 09:22:44.650  3352  3352 V APM_AudioPolicyManager: getNewOutputDevice() selected device 2
    11-23 09:22:44.650  3352  3352 V APM_AudioPolicyManager: setOutputDevice() device 0002 delayMs 0
    11-23 09:22:44.650  3352  3352 V APM_AudioPolicyManager: setOutputDevice() prevDevice 0x0002
    11-23 09:22:44.650  3352  3352 V APM_AudioPolicyManager: setOutputDevice() setting same device 0x0002 or null device
    11-23 09:22:44.650  3352  3352 I AudioFlinger: updateStageIndex prev 0, new -2101
    11-23 09:22:44.656  3299  6286 V audio_hw_primary: start_output_stream+, out->device : 00000002 , out->type = 1
    11-23 09:22:44.656  3299  6286 D audio_hw_primary: start_output_stream jack_skip_check false
    11-23 09:22:44.686  3299  6286 D audio_hw_primary: start_output_stream (0xecc84340) out->pcm_device:6 out->config.rate:48000 out->config.format:0 out->period_size:240
    11-23 09:22:44.688  3299  6286 D audio_hw_primary: start_output_stream (0xecc84340) out->config.rate:48000 out->config.format:0 out->period_size:240
    11-23 09:22:44.688  3299  6286 V audio_hw_primary: select_devices output_scenario:0 input_scenario:-1 out_snd_device 0x2 in_snd_device:0x0
    11-23 09:22:44.688  3299  6286 I audio_route: > audio_route_reset :
    11-23 09:22:44.689  3299  6286 I audio_route: > audio_route_apply_path : "media-speaker"
    11-23 09:22:44.689  3299  6286 I audio_route: > audio_route_update_path : "media-speaker" reverse(0)
    11-23 09:22:44.807  3299  6286 V audio_hw_primary: select_devices() output_route "media-speaker" 
    11-23 09:22:44.807  3299  6286 I audio_route: > audio_route_apply_path : "gain-media-speaker"
    11-23 09:22:44.807  3299  6286 I audio_route: > audio_route_update_path : "gain-media-speaker" reverse(0)
    11-23 09:22:44.808  3299  6286 V audio_hw_primary: select_devices() output_gain "gain-media-speaker" 
    11-23 09:22:44.808  3299  6286 I audio_route: > audio_route_update_mixer : +
    11-23 09:22:44.808  3299  6286 I audio_route: > audio_route_update_mixer : changed(0) -
    11-23 09:22:44.808  3299  6286 I audio_hw_primary: select_devices - 
    11-23 09:22:44.808  3299  6286 V audio_hw_primary: start_output_stream-
    11-23 09:22:44.832  3352  3706 D AudioFlinger: mixer(0xf2883340) Spend too much time to write: delta 175(effect 0, stage 0)
    11-23 09:22:44.919  3352  3562 V APM_AudioPolicyManager: stopOutput() output 21, stream 1, session 17
    11-23 09:22:44.919  3352  3562 V APM_AudioPolicyManager: setBeaconMute(1) mBeaconMuteRefCount=0 mBeaconPlayingRefCount=0
    11-23 09:22:44.919  3352  3562 V APM_AudioPolicyManager: getNewOutputDevice() selected device 0
    11-23 09:22:44.919  3352  3562 V APM_AudioPolicyManager: setOutputDevice() device 0000 delayMs 100
    11-23 09:22:44.919  3352  3562 V APM_AudioPolicyManager: setOutputDevice() prevDevice 0x0002
    11-23 09:22:44.919  3352  3562 V APM_AudioPolicyManager: setOutputDevice() setting same device 0x0000 or null device
    11-23 09:22:45.581  3309  3309 I android.hardware.wifi@1.0-service: getLinkLayerStats
    11-23 09:22:45.970  3675  5796 D GameManagerService: identifyGamePackage. at.bitfire.davdroid
    11-23 09:22:45.970  3675  5796 D GameManagerService: GameService deos not exist
    11-23 09:22:46.049  3675  7036 D BatteryService: !@BatteryListener : batteryPropertiesChanged!
    11-23 09:22:46.050  3675  7036 D BatteryService: level:94, scale:100, status:2, health:2, present:true, voltage: 4203, temperature: 265, technology: Li-ion, AC powered:false, USB powered:true, POGO powered:false, Wireless powered:false, icon:17303851, invalid charger:0, maxChargingCurrent:0, maxChargingVoltage:0, chargeCounter:0
    11-23 09:22:46.050  3675  7036 D BatteryService: online:4, current avg:248, charge type:1, power sharing:false, high voltage charger:false, capacity:280000, batterySWSelfDischarging:false, misc_event:0, current_event:0, current_now:257
    11-23 09:22:46.051  3675  3675 D BatteryService: Sending ACTION_BATTERY_CHANGED.
    11-23 09:22:46.059  3675  3675 I MotionRecognitionService: Plugged
    11-23 09:22:46.060  3675  3675 D MotionRecognitionService:   mCableConnection= 1
    11-23 09:22:46.060  3675  3675 D MotionRecognitionService: setPowerConnected : mGripEnabled = false
    11-23 09:22:46.060  3675  3675 D SamsungPhoneWindowManager: ACTION_BATTERY_CHANGED - Level :: 94, battStatus :: 2
    11-23 09:22:46.063  3675  3761 D UsbDeviceManager: handleMessage -> MSG_UPDATE_CHARGING_STATE = 1
    11-23 09:22:46.069  3675  7036 W StorageManager: getStorageLowBytes lowPercent : 5, lowBytes : 6047467520, maxLowBytes : 524288000
    11-23 09:22:46.119  2650  2783 D AppMonet/BidManager: syncing bidmanager with pool
    11-23 09:22:46.119  3675 10354 W StorageManager: getStorageLowBytes lowPercent : 5, lowBytes : 6047467520, maxLowBytes : 524288000
    11-23 09:22:46.119  2650  2783 D AppMonet/PubSubService: Message Topic -> cleanUpBids
    11-23 09:22:46.128  4140  4140 D KeyguardUpdateMonitor: received broadcast android.intent.action.BATTERY_CHANGED
    11-23 09:22:46.129  4140  4140 D BatteryController: onReceive-ACTION_BATTERY_CHANGED : mLevel=94, mBatteryStatus=2
    11-23 09:22:46.134  4140  4140 D PowerUI : priorPlugType = 2 mPlugType =  2
    11-23 09:22:46.135  4140  4140 D PowerUI.Notification: showChargingNotice oldChargingType : 1 currentChargingType : 1 oldChargingTime : 1284000 mChargingTime : 1284000
    11-23 09:22:46.135  4140  4140 D PowerUI.Notification: There is no change about charging status, so return!
    11-23 09:22:47.733  3675  3686 I zygote64: Background concurrent copying GC freed 38455(2MB) AllocSpace objects, 22(636KB) LOS objects, 40% free, 34MB/58MB, paused 1.094ms total 249.150ms
    11-23 09:22:47.888  3299  3481 I audio_hw_primary: do_out_standby +
    11-23 09:22:47.898  3299  3481 D audio_hw_primary: output_devices devices:0
    11-23 09:22:47.898  3299  3481 D audio_hw_primary: output_devices devices:0
    11-23 09:22:47.898  3299  3481 V audio_hw_primary: select_devices output_scenario:-1 input_scenario:-1 out_snd_device 0x0 in_snd_device:0x0
    11-23 09:22:47.898  3299  3481 I audio_hw_primary: set_spk_rx_mute mute(1), rx val=0
    11-23 09:22:47.940  3299  3481 I audio_route: > audio_route_reset :
    11-23 09:22:47.941  3299  3481 I audio_route: > audio_route_update_mixer : +
    11-23 09:22:48.001  3299  3481 I audio_route: > audio_route_update_mixer : changed(2) -
    11-23 09:22:48.001  3299  3481 I audio_hw_primary: select_devices - 
    11-23 09:22:48.001  3299  3481 I audio_hw_primary: do_out_standby -
    11-23 09:22:48.437  4741  4741 D io_stats: !@   8,0 r 170319 11831980 w 183939 3175288 d 29159 1129172 f 292 292 iot 131060 101856 th 229764 0 0 pt 0 inp 0 0 38899.504
    

    As said before, I had checked this output, and it includes nothing relevant IMHO, but here it is.



  • It's working again!

    Here is what I did: I discovered that Firefox had also not been syncing in the last couple of days. So I went to the settings and asked it to "synchronize now". This took quite a long time at first, but then I got a toast saying that "auto-sync timers were started", and Firefox synchronised.

    Sure enough, when I went to DavDroid and hit sync, it started to sync. YEAH!

    So something stopped Android sync timers, and even a reboot didn't fix that. I'd love to find out, but meanwhile, maybe we can learn from Firefox and make sure that DavDroid can at least detect this situation, if not even fix it (like Firefox apparently could).



  • I just switched Wifi networks while a sync was running, and now it's no longer sync'ing. Also, the "Firefox method" doesn't work this time, i.e. I cannot even manually sync Firefox.

    Still figuring this out…





  • I did a dirty reflash of the ROM and wiped Dalvik/Cache, and it's been working since then. Still curious to find out what happened… let's see if it comes back!



  • It's back within less than a day. The "Firefox method" doesn't work, and neither does restarting.

    Wiping cache and Dalvik does seem to make it work again. Now I feel like I have a lead, and will try wiping app caches instead of Dalvik next time it happens.

    I do wonder what the system app behind the sync threads are. Any idea?



  • This issue is still ongoing, and it's a real pain as I cannot use my calendar on the device. I am at the point where I will need to reinstall, which is just terrible to be honest, because it's such a waste of time. I'll try one more time and maybe you guys have an idea? cc. @devvv4ever @rfc2822

    If DAVDroid and Firefox are both using the Android Sync Framework, and both are not syncing, then maybe the problem is with the sync framework. If I manually tell Firefox to run a sync, the logs will just show:

    I FxAccounts: firefox :: FirefoxAccounts :: Requesting sync.
    I FxAccounts: firefox :: FirefoxAccounts :: Sync options -- scheduling now: true
    

    If I manually tell DAVDroid to sync, I get no log output. There is a toast saying "Synchronize now" for 5 seconds, but no progress indicator appears under the calendar/addressbook resources, as it would when an actual sync is running. This makes me think that maybe the same thing is happening, i.e. the sync is being scheduled, but then never executed.

    I am not sure how the Android Sync Service works, or how to verify that it works. But I did stumble over this explanation of how Oreo changed wrt. background services, and since the problem started to appear after my upgrade to Oreo, I wonder if there is maybe a lead here? Could it be that DAVDroid is still using AlarmManager, rather than JobScheduler? A grep of the source code unfortunately revealed no matches for either.

    I also found the following log entries during boot, which may well be related too:

    11-30 10:44:29.552  4057  4057 W AlarmManagerEXT: Out of bounds, Allowed Values 1s ~ 3600s, Setting syncInterval : 300000
    11-30 10:44:29.552  4057  4057 W AlarmManagerEXT: Out of bounds, Allowed Values 1s ~ 225s, Setting deltaFromTriggers : 10000
    […]
    11-30 10:44:31.874  4057  4620 E Watchdog: !@Sync 0 [2018-11-30 10:44:31.874]
    […]
    11-30 10:44:32.709  4057  4057 W ContextImpl: Calling a method in the system process without a qualified user: android.app.ContextImpl.startService:0 com.android.server.content.SyncManager$13.run:8 android.os.Handler.handleCallback:2 android.os.Handler.dispatchMessage:4 android.os.Looper.loop:139
    

    At least the first two suggest that something is wrong with AlarmManager, which is somehow set to run every 300000s, which is almost 4 days. However, the last successful sync is now 6 days old.

    So I am really at a loss, and would greatly appreciate any help or insights.

    Thank you,
    martin



  • I found out more stuff.

    So in the Android settings dialog, under accounts, if I go to a DAVDroid account and choose "Sync Account", I take note that all syncs are enabled.

    If I choose "sync now" under the menu, nothing happens, except the menu changes to "cancel sync". If I choose "cancel sync", then it goes back to sync now.

    Toggling the slider on e.g. "Sync Calendar" has no effect.

    Except I've seen the arrow-circle start turning (though the DAV server sees no traffic). And occasionally, I've now run into the error message at the bottom, that "Sync is currently experiencing problems. It will be back shortly":

    0_1543533997596_Screenshot_20181130-121519_Settings.jpg

    Nothing in logcat about that though.

    Finally, I took note that every time I want to sync with DAVDroid, the following is logged:

    11-30 12:20:05.139  4075  5727 D SecContentProvider: query(), uri = 16 selection = isGoogleAccountsAutoSyncAllowed
    

    I do not have any Google accounts or services running on this phone, and I don't think that this should really affect DAVDroid either, because it has sync'd in the past on this install.

    Please help. 😞



  • Hi madduck,

    sorry, I can't provide any help in here - just wanted to give you one more voice.
    Thanks for your research so far!

    I have exactly the same problem:

    • first -time setup works fine, calendars are synced
    • "some" time later (about next day) syncing stops
    • manual sync has no effect except toast showing "syncing started" - the "colored moving line" which usually comes up while syncing does not show
    • nothing to find in logs (logcat nor davdroid logs)
    • no (HTTP-)request is logged by the server
    • (manual) reloading the calendars (not the events, "Kalender neu erkennen") works fine
    • manual re-installation of Android re-enables the sync, scheduled and manual sync works fine
    • wiping DALVIK/ART-cache re-enables syncing

    My phone is on LineageOS 15.1 = Android 8.1.0

    As I don't sync any other services/apps I can't check the alternatives.

    Regards
    MG



  • Well - I have to correct one thing in my list above:

    • it's not necessary to wipe the DALVIK-cache, a reboot re-enables the sync (on reboot the calendars are synced immediately, manual sync works also)

    Cheers
    MG



  • Hey @MadGoose, thanks for the input. Are you using something like TitantiumBackup to freeze services?

    Here is what I found out recently:

    I have been freezing Google and Samsung software that unfortunately comes pre-installed. It turns out that the Android sync framework, while independent (and a core service of Android), does somehow link into these services. Long story short — I don't really understand all this — I thawed the services, rebooted and wiped Dalvik/Cache, then refroze the services after the boot, and now it's working fine again.

    I wish I knew what's going on…