SyncJobStatus is not triggered for Finish state for android 13

[anchita-g]

Describe the bug
A clear and concise description of what the bug is.

Component
Core library

To Reproduce
Steps to reproduce the behavior:

1. Go to '...'
2. Click on '....'
3. Scroll down to '....'
4. See error

Expected behavior
A clear and concise description of what you expected to happen.

Screenshots
If applicable, add screenshots to help explain your problem.

Smartphone (please complete the following information):

• Device: [e.g. Pixel4a emulator]
• Android version: [e.g. Settings -> About phone -> Android version]
• Build number: [e.g. Settings -> About phone -> Build number]
• Version [e.g. 22]

Additional context
Add any other context about the problem here.

Would you like to work on the issue?
Please state if this issue should be assigned to you or who you think could help to solve this issue.

[anchita-g]

@khyativyasargus Could you please help us with the details, specifically on the steps to reproduce.

[khyativyasargus]

@khyativyasargus Could you please help us with the details, specifically on the steps to reproduce.

Hi @anchita-g , yes sure!

1. Go to PatientListFragment into demo app source code
2. Observe SyncJobStatus into mainActivityViewModel.pollState.collect {} for different states of sync job, put logs there
3. Run demo app in Android 13 & observe logs , you'll notice SyncJobStatus.Finished doesn't get triggered in Android 13, but it works fine for Android 12

[khyativyasargus]

Hi @anchita-g , I hope the given explanation was helpful. Let me know if there is any update on this as it's kinda high priority for Emcare.

[anchita-g]

Hi @khyativyasargus , thank you for the details on the issue. Yes we are looking into this right now. @santosh-pingle would you be able to provide some updates on this?

[santosh-pingle]

@anchita-g
I've already updated @khyativyasargus in the weekly call that issue is reproducible and I am looking into it.

[santosh-pingle]

Actually, issue is only reproducible on android api 33 (android 13) issue can be observed on other android api as well.
sync/FhirSyncWorker

override suspend fun doWork(): Result {
...
val job =
      CoroutineScope(Dispatchers.IO).launch {
...
if (it is SyncJobStatus.Finished || it is SyncJobStatus.Failed) {
            this@launch.cancel()
          }
...
...

It looks like the Finished state does not get published observed when the coroutine scope is cancelled. However, if you delay the coroutine scope cancellation operation by adding delay(), then the issue is not observed.

[santosh-pingle]

In PeriodicSyncWorker, when FhirSyncWorker updates the finished state, by the time the progress observer listens to it, FhirSyncWorker's state becomes ENQUEUE.

As per Android guide, progress information can only be observed and updated while the ListenableWorker is running.
https://developer.android.com/guide/background/persistent/how-to/observe

[santosh-pingle]

@khyativyasargus @omarismail94 @jingtang10

[santosh-pingle]

The following log was captured on top of pr #2053 with oneTimeSyncRequest, where the Finished state is observed in the demo app.

023-07-10 23:24:47.887 11614-11614/com.google.android.fhir.demo I/MainActivityViewModel$triggerOneTimeSync: sync: one time sync InProgress(syncOperation=DOWNLOAD, total=342, completed=140)
2023-07-10 23:24:47.888 11614-11614/com.google.android.fhir.demo D/PatientListFragment$onViewCreated: onViewCreated: pollState Got status InProgress(syncOperation=DOWNLOAD, total=342, completed=140)
2023-07-10 23:24:47.888 11614-11614/com.google.android.fhir.demo I/PatientListFragment$onViewCreated: Sync: InProgress with data InProgress(syncOperation=DOWNLOAD, total=342, completed=140)
2023-07-10 23:24:48.667 11614-11614/com.google.android.fhir.demo I/MainActivityViewModel$triggerOneTimeSync: sync: one time sync InProgress(syncOperation=DOWNLOAD, total=342, completed=160)
2023-07-10 23:24:48.667 11614-11614/com.google.android.fhir.demo D/PatientListFragment$onViewCreated: onViewCreated: pollState Got status InProgress(syncOperation=DOWNLOAD, total=342, completed=160)
2023-07-10 23:24:48.667 11614-11614/com.google.android.fhir.demo I/PatientListFragment$onViewCreated: Sync: InProgress with data InProgress(syncOperation=DOWNLOAD, total=342, completed=160)
2023-07-10 23:24:49.506 11614-11614/com.google.android.fhir.demo I/MainActivityViewModel$triggerOneTimeSync: sync: one time sync InProgress(syncOperation=DOWNLOAD, total=342, completed=180)
2023-07-10 23:24:49.507 11614-11614/com.google.android.fhir.demo D/PatientListFragment$onViewCreated: onViewCreated: pollState Got status InProgress(syncOperation=DOWNLOAD, total=342, completed=180)
2023-07-10 23:24:49.507 11614-11614/com.google.android.fhir.demo I/PatientListFragment$onViewCreated: Sync: InProgress with data InProgress(syncOperation=DOWNLOAD, total=342, completed=180)
2023-07-10 23:24:50.309 11614-11614/com.google.android.fhir.demo I/MainActivityViewModel$triggerOneTimeSync: sync: one time sync InProgress(syncOperation=DOWNLOAD, total=342, completed=200)
2023-07-10 23:24:50.309 11614-11614/com.google.android.fhir.demo D/PatientListFragment$onViewCreated: onViewCreated: pollState Got status InProgress(syncOperation=DOWNLOAD, total=342, completed=200)
2023-07-10 23:24:50.309 11614-11614/com.google.android.fhir.demo I/PatientListFragment$onViewCreated: Sync: InProgress with data InProgress(syncOperation=DOWNLOAD, total=342, completed=200)
2023-07-10 23:24:51.150 11614-11614/com.google.android.fhir.demo I/MainActivityViewModel$triggerOneTimeSync: sync: one time sync InProgress(syncOperation=DOWNLOAD, total=342, completed=220)
2023-07-10 23:24:51.151 11614-11614/com.google.android.fhir.demo D/PatientListFragment$onViewCreated: onViewCreated: pollState Got status InProgress(syncOperation=DOWNLOAD, total=342, completed=220)
2023-07-10 23:24:51.152 11614-11614/com.google.android.fhir.demo I/PatientListFragment$onViewCreated: Sync: InProgress with data InProgress(syncOperation=DOWNLOAD, total=342, completed=220)
2023-07-10 23:24:51.972 11614-11614/com.google.android.fhir.demo I/MainActivityViewModel$triggerOneTimeSync: sync: one time sync InProgress(syncOperation=DOWNLOAD, total=342, completed=240)
2023-07-10 23:24:51.973 11614-11614/com.google.android.fhir.demo D/PatientListFragment$onViewCreated: onViewCreated: pollState Got status InProgress(syncOperation=DOWNLOAD, total=342, completed=240)
2023-07-10 23:24:51.974 11614-11614/com.google.android.fhir.demo I/PatientListFragment$onViewCreated: Sync: InProgress with data InProgress(syncOperation=DOWNLOAD, total=342, completed=240)
2023-07-10 23:24:52.750 11614-11614/com.google.android.fhir.demo I/MainActivityViewModel$triggerOneTimeSync: sync: one time sync InProgress(syncOperation=DOWNLOAD, total=342, completed=260)
2023-07-10 23:24:52.751 11614-11614/com.google.android.fhir.demo D/PatientListFragment$onViewCreated: onViewCreated: pollState Got status InProgress(syncOperation=DOWNLOAD, total=342, completed=260)
2023-07-10 23:24:52.751 11614-11614/com.google.android.fhir.demo I/PatientListFragment$onViewCreated: Sync: InProgress with data InProgress(syncOperation=DOWNLOAD, total=342, completed=260)
2023-07-10 23:24:53.784 11614-11614/com.google.android.fhir.demo I/MainActivityViewModel$triggerOneTimeSync: sync: one time sync InProgress(syncOperation=DOWNLOAD, total=342, completed=280)
2023-07-10 23:24:53.785 11614-11614/com.google.android.fhir.demo D/PatientListFragment$onViewCreated: onViewCreated: pollState Got status InProgress(syncOperation=DOWNLOAD, total=342, completed=280)
2023-07-10 23:24:53.785 11614-11614/com.google.android.fhir.demo I/PatientListFragment$onViewCreated: Sync: InProgress with data InProgress(syncOperation=DOWNLOAD, total=342, completed=280)
2023-07-10 23:24:54.519 11614-11614/com.google.android.fhir.demo I/MainActivityViewModel$triggerOneTimeSync: sync: one time sync InProgress(syncOperation=DOWNLOAD, total=342, completed=300)
2023-07-10 23:24:54.521 11614-11614/com.google.android.fhir.demo D/PatientListFragment$onViewCreated: onViewCreated: pollState Got status InProgress(syncOperation=DOWNLOAD, total=342, completed=300)
2023-07-10 23:24:54.522 11614-11614/com.google.android.fhir.demo I/PatientListFragment$onViewCreated: Sync: InProgress with data InProgress(syncOperation=DOWNLOAD, total=342, completed=300)
2023-07-10 23:24:56.010 11614-11614/com.google.android.fhir.demo I/MainActivityViewModel$triggerOneTimeSync: sync: one time sync InProgress(syncOperation=DOWNLOAD, total=342, completed=320)
2023-07-10 23:24:56.011 11614-11614/com.google.android.fhir.demo D/PatientListFragment$onViewCreated: onViewCreated: pollState Got status InProgress(syncOperation=DOWNLOAD, total=342, completed=320)
2023-07-10 23:24:56.011 11614-11614/com.google.android.fhir.demo I/PatientListFragment$onViewCreated: Sync: InProgress with data InProgress(syncOperation=DOWNLOAD, total=342, completed=320)
2023-07-10 23:24:56.778 11614-11614/com.google.android.fhir.demo I/MainActivityViewModel$triggerOneTimeSync: sync: one time sync InProgress(syncOperation=DOWNLOAD, total=342, completed=340)
2023-07-10 23:24:56.778 11614-11614/com.google.android.fhir.demo D/PatientListFragment$onViewCreated: onViewCreated: pollState Got status InProgress(syncOperation=DOWNLOAD, total=342, completed=340)
2023-07-10 23:24:56.778 11614-11614/com.google.android.fhir.demo I/PatientListFragment$onViewCreated: Sync: InProgress with data InProgress(syncOperation=DOWNLOAD, total=342, completed=340)
2023-07-10 23:24:57.366 11614-11614/com.google.android.fhir.demo I/MainActivityViewModel$triggerOneTimeSync: sync: one time sync InProgress(syncOperation=DOWNLOAD, total=342, completed=342)
2023-07-10 23:24:57.367 11614-11614/com.google.android.fhir.demo D/PatientListFragment$onViewCreated: onViewCreated: pollState Got status InProgress(syncOperation=DOWNLOAD, total=342, completed=342)
2023-07-10 23:24:57.367 11614-11614/com.google.android.fhir.demo I/PatientListFragment$onViewCreated: Sync: InProgress with data InProgress(syncOperation=DOWNLOAD, total=342, completed=342)
2023-07-10 23:24:57.417 11614-11687/com.google.android.fhir.demo D/FhirSyncWorker: Received result from worker com.google.android.fhir.sync.SyncJobStatus$Finished@b25750a and sending output Data {StateType : com.google.android.fhir.sync.SyncJobStatus$Finished, State : {"timestamp":"2023-07-10T23:24:57.41+05:30"}, }
2023-07-10 23:24:57.421 11614-11650/com.google.android.fhir.demo I/WM-WorkerWrapper: Worker result SUCCESS for Work [ id=9f1e27b3-5e56-4d7f-9cec-351329a2ba38, tags={ com.google.android.fhir.demo.data.FhirSyncWorker } ]
2023-07-10 23:24:57.437 11614-11614/com.google.android.fhir.demo I/MainActivityViewModel$triggerOneTimeSync: sync: one time sync com.google.android.fhir.sync.SyncJobStatus$Finished@6ec5944
2023-07-10 23:24:57.438 11614-11614/com.google.android.fhir.demo D/PatientListFragment$onViewCreated: onViewCreated: pollState Got status com.google.android.fhir.sync.SyncJobStatus$Finished@6ec5944
2023-07-10 23:24:57.438 11614-11614/com.google.android.fhir.demo I/PatientListFragment$onViewCreated: Sync: Finished at 2023-07-10T23:24:57.410+05:30

[santosh-pingle]

I was just checking whether the last progress update would be observed in periodic sync with simple demo changes without flow, but I didn't see the last update get observed until an extra delay was added between setProgress() and the return call from the doWork() API.
PR #2067

[santosh-pingle]

@aditya-07

[omarismail94]

Can you cherry pick the commit from: #2064 to update the dependecies. you wll need to have Java 17 installed for this to work

[khyativyasargus]

Can you cherry pick the commit from: #2064 to update the dependecies. you wll need to have Java 17 installed for this to work

Hi @omarismail94 We checked with this commit #2064 with demo app, but sync Finish state isn't being observed still.

[santosh-pingle]

fixed with #2142