tmo1 / sms-ie

SMS Import / Export is a simple Android app that imports and exports SMS and MMS messages, call logs, and contacts from and to JSON / NDJSON files.
GNU General Public License v3.0
312 stars 38 forks source link

Fix notification issues #187

Closed chenxiaolong closed 1 month ago

chenxiaolong commented 1 month ago

Please see the individual commits for more details.

Changes:

Fixes: #34 Fixes: #179 Probably improves: #183

tmo1 commented 1 month ago

Wow, thanks so much for all this! So IIUC, the main problem here was that the call to schedule the next export job was keeping the foreground service running - indefinitely?! Why? It had occurred to me that that could somehow be the problem, but I don't get it: I would think that after the call to schedule the job returns, the foreground service should end.

chenxiaolong commented 1 month ago

No problem!

I would think that after the call to schedule the job returns, the foreground service should end.

I did some further investigation into this and I think I have a better idea of what's going on now.

With or without the workaround, the service actually does exit. I confirmed this by running:

adb shell dumpsys activity services sms_ie

during and after the scheduled export. After the export completes, the search returns nothing. It seems like the only negative side effect without the workaround is that the notification not being dismissed, not any additional battery drain or anything like that.

So then I enabled the androidx work library's debug logging with: https://developer.android.com/develop/background-work/background-tasks/testing/persistent/debug. The step for what to add to AndroidManifest.xml is actually wrong and should be:

<provider
    android:name="androidx.startup.InitializationProvider"
    android:exported="false"
    android:authorities="${applicationId}.androidx-startup">
    <meta-data
        android:name="androidx.work.WorkManagerInitializer"
        android:value="androidx.startup"
        tools:node="remove" />
</provider>

With debug debug logging in place, this is what happens for the scheduled exports with and without the workaround:

Without workaround (click to expand) ``` 2024-05-26 13:02:00.095507 -0400 D/WM-DelayedWorkTracker(22265): Scheduling work 60e55dcb-5ecc-4cdd-be88-5bf50f5e8071 2024-05-26 13:02:00.096291 -0400 D/WM-GreedyScheduler(22265): Starting work for 60e55dcb-5ecc-4cdd-be88-5bf50f5e8071 2024-05-26 13:02:00.105405 -0400 D/WM-Processor(22265): Processor: processing WorkGenerationalId(workSpecId=60e55dcb-5ecc-4cdd-be88-5bf50f5e8071, generation=0) 2024-05-26 13:02:00.109281 -0400 D/CompatibilityChangeReporter(22265): Compat change id reported: 263076149; UID 10215; state: ENABLED 2024-05-26 13:02:00.119966 -0400 D/WM-WorkerWrapper(22265): Starting work for com.github.tmo1.sms_ie.ExportWorker 2024-05-26 13:02:00.139515 -0400 I/WM-Processor(22265): Moving WorkSpec (60e55dcb-5ecc-4cdd-be88-5bf50f5e8071) to the foreground 2024-05-26 13:02:00.161680 -0400 I/WM-SystemFgDispatcher(22265): Started foreground service Intent { act=ACTION_START_FOREGROUND cmp=com.github.tmo1.sms_ie.debug/androidx.work.impl.foreground.SystemForegroundService (has extras) } 2024-05-26 13:02:00.162761 -0400 D/WM-SystemFgDispatcher(22265): Notifying with (id:0, workSpecId: 60e55dcb-5ecc-4cdd-be88-5bf50f5e8071, notificationType :1073741824) 2024-05-26 13:02:00.163828 -0400 D/WM-SystemFgDispatcher(22265): Notifying with (id:0, workSpecId: 60e55dcb-5ecc-4cdd-be88-5bf50f5e8071, notificationType :1073741824) 2024-05-26 13:02:00.205638 -0400 I/SMSIE (22265): Beginning call log export ... 2024-05-26 13:02:02.035320 -0400 W/o1.sms_ie.debug(22265): Cleared Reference was only reachable from finalizer (only reported once) 2024-05-26 13:02:08.601713 -0400 I/SMSIE (22265): Call log export successful: 498 calls exported 2024-05-26 13:02:08.679342 -0400 I/SMSIE (22265): Beginning contacts export ... 2024-05-26 13:02:11.485152 -0400 I/SMSIE (22265): Contacts export successful: 77 contacts exported 2024-05-26 13:02:11.495052 -0400 D/SMSIE (22265): Scheduling backup for 86388506 milliseconds from now 2024-05-26 13:02:11.520721 -0400 D/WM-Processor(22265): Processor cancelling 60e55dcb-5ecc-4cdd-be88-5bf50f5e8071 2024-05-26 13:02:11.527151 -0400 I/WM-SystemFgDispatcher(22265): Stopping foreground service 2024-05-26 13:02:11.527365 -0400 D/WM-SystemFgService(22265): All commands completed. 2024-05-26 13:02:11.527588 -0400 D/WM-WorkerWrapper(22265): Work interrupted for Work [ id=60e55dcb-5ecc-4cdd-be88-5bf50f5e8071, tags={ com.github.tmo1.sms_ie.ExportWorker, export } ] 2024-05-26 13:02:11.543541 -0400 D/WM-PackageManagerHelper(22265): androidx.work.impl.background.systemalarm.RescheduleReceiver disabled 2024-05-26 13:02:11.546142 -0400 D/WM-WorkerWrapper(22265): WorkSpec {WorkSpec: 60e55dcb-5ecc-4cdd-be88-5bf50f5e8071} is already done. Not interrupting. 2024-05-26 13:02:11.546296 -0400 D/WM-Processor(22265): Processor 60e55dcb-5ecc-4cdd-be88-5bf50f5e8071 executed; reschedule = false 2024-05-26 13:02:11.546586 -0400 D/WM-Processor(22265): WorkerWrapper interrupted for 60e55dcb-5ecc-4cdd-be88-5bf50f5e8071 2024-05-26 13:02:11.563337 -0400 D/WM-GreedyScheduler(22265): Cancelling work ID 60e55dcb-5ecc-4cdd-be88-5bf50f5e8071 2024-05-26 13:02:11.603134 -0400 D/WM-PackageManagerHelper(22265): androidx.work.impl.background.systemalarm.RescheduleReceiver enabled 2024-05-26 13:02:11.625917 -0400 D/WM-SystemJobScheduler(22265): Scheduling work ID be358c82-9ade-4913-888c-da882af21caaJob ID 24 2024-05-26 13:02:11.629902 -0400 D/WM-WorkerWrapper(22265): com.github.tmo1.sms_ie.ExportWorker returned a Success {mOutputData=Data {}}. 2024-05-26 13:02:11.629999 -0400 D/WM-WorkerWrapper(22265): Work interrupted for Work [ id=60e55dcb-5ecc-4cdd-be88-5bf50f5e8071, tags={ com.github.tmo1.sms_ie.ExportWorker, export } ] 2024-05-26 13:02:11.634720 -0400 D/WM-GreedyScheduler(22265): Cancelling work ID 60e55dcb-5ecc-4cdd-be88-5bf50f5e8071 ```
With workaround (click to expand) ``` 2024-05-26 13:04:00.040765 -0400 D/WM-DelayedWorkTracker(22521): Scheduling work 35be77c3-294e-403d-8056-8c926904b155 2024-05-26 13:04:00.041325 -0400 D/WM-GreedyScheduler(22521): Starting work for 35be77c3-294e-403d-8056-8c926904b155 2024-05-26 13:04:00.053847 -0400 D/WM-Processor(22521): Processor: processing WorkGenerationalId(workSpecId=35be77c3-294e-403d-8056-8c926904b155, generation=0) 2024-05-26 13:04:00.058652 -0400 D/CompatibilityChangeReporter(22521): Compat change id reported: 263076149; UID 10215; state: ENABLED 2024-05-26 13:04:00.078319 -0400 D/WM-WorkerWrapper(22521): Starting work for com.github.tmo1.sms_ie.ExportWorker 2024-05-26 13:04:00.089918 -0400 D/WM-SystemJobService(22521): onStartJob for WorkGenerationalId(workSpecId=35be77c3-294e-403d-8056-8c926904b155, generation=0) 2024-05-26 13:04:00.096878 -0400 D/WM-Processor(22521): Work WorkGenerationalId(workSpecId=35be77c3-294e-403d-8056-8c926904b155, generation=0) is already enqueued for processing 2024-05-26 13:04:00.103045 -0400 I/WM-Processor(22521): Moving WorkSpec (35be77c3-294e-403d-8056-8c926904b155) to the foreground 2024-05-26 13:04:00.123153 -0400 I/WM-SystemFgDispatcher(22521): Started foreground service Intent { act=ACTION_START_FOREGROUND cmp=com.github.tmo1.sms_ie.debug/androidx.work.impl.foreground.SystemForegroundService (has extras) } 2024-05-26 13:04:00.124069 -0400 D/WM-SystemFgDispatcher(22521): Notifying with (id:0, workSpecId: 35be77c3-294e-403d-8056-8c926904b155, notificationType :1073741824) 2024-05-26 13:04:00.124871 -0400 D/WM-SystemFgDispatcher(22521): Notifying with (id:0, workSpecId: 35be77c3-294e-403d-8056-8c926904b155, notificationType :1073741824) 2024-05-26 13:04:00.165055 -0400 I/SMSIE (22521): Beginning call log export ... 2024-05-26 13:04:07.252054 -0400 I/SMSIE (22521): Call log export successful: 498 calls exported 2024-05-26 13:04:07.338879 -0400 I/SMSIE (22521): Beginning contacts export ... 2024-05-26 13:04:10.112461 -0400 I/SMSIE (22521): Contacts export successful: 77 contacts exported 2024-05-26 13:04:10.120787 -0400 D/WM-WorkerWrapper(22521): com.github.tmo1.sms_ie.ExportWorker returned a Success {mOutputData=Data {}}. 2024-05-26 13:04:10.123477 -0400 D/SMSIE (22521): Scheduling backup for 86389879 milliseconds from now 2024-05-26 13:04:10.124791 -0400 I/WM-WorkerWrapper(22521): Worker result SUCCESS for Work [ id=35be77c3-294e-403d-8056-8c926904b155, tags={ com.github.tmo1.sms_ie.ExportWorker, export } ] 2024-05-26 13:04:10.132142 -0400 D/WM-PackageManagerHelper(22521): androidx.work.impl.background.systemalarm.RescheduleReceiver disabled 2024-05-26 13:04:10.137257 -0400 D/WM-Processor(22521): Processor 35be77c3-294e-403d-8056-8c926904b155 executed; reschedule = false 2024-05-26 13:04:10.137574 -0400 D/WM-SystemJobService(22521): 35be77c3-294e-403d-8056-8c926904b155 executed on JobScheduler 2024-05-26 13:04:10.137778 -0400 D/WM-SystemFgDispatcher(22521): Removing Notification (id: 0, workSpecId: WorkGenerationalId(workSpecId=35be77c3-294e-403d-8056-8c926904b155, generation=0), notificationType: 1073741824 2024-05-26 13:04:10.138029 -0400 I/WM-SystemFgDispatcher(22521): Stopping foreground service 2024-05-26 13:04:10.138070 -0400 D/WM-SystemFgService(22521): All commands completed. 2024-05-26 13:04:10.145945 -0400 D/WM-PackageManagerHelper(22521): androidx.work.impl.background.systemalarm.RescheduleReceiver enabled 2024-05-26 13:04:10.169232 -0400 D/WM-SystemJobScheduler(22521): Scheduling work ID e27daf6d-df9f-44da-bdd8-e6ca8adf695cJob ID 27 2024-05-26 13:04:10.176308 -0400 D/WM-GreedyScheduler(22521): Cancelling work ID 35be77c3-294e-403d-8056-8c926904b155 ```

The thing that caught my eye is that without the workaround, the library is treating the job as being cancelled (Work interrupted for Work) instead of completing successfully (Worker result SUCCESS for Work). Somehow this prevents the library for executing the logic for clearing the notification (Removing Notification (id: 0<...>).

I guess it's just undocumented behavior that scheduling a new job within a running job causes the running job to be cancelled and that cancelled jobs don't dismiss the foreground notification.

chenxiaolong commented 1 month ago

(I will update the commit description to reflect what I've posted here ^^)

EDIT: Done!

chenxiaolong commented 1 month ago

Oh wait! The job is getting cancelled because updateExportWork() is explicitly cancelling it. I completely missed that.

I've updated the branch with a new approach. 6d988c7f7e6ea7fd53baa6615c474b9a0c854054 should fix this properly (simpler and without any ugly workarounds).

tmo1 commented 1 month ago

So ultimately it was at least partially my fault, for not remebering that we were cancelling the old job when rescheduling the new one (and not realizng the ramifications thereof) and the fix was simple: don't cancel when rescheduling upon job completion. Thanks so much for figuring this out!

The truth is that I really don't much like the current paradigm of continually rescheduling the next job upon completion of the previous one. It feels hackish, and if something goes wrong and a job crashes, I suppose that no further ones will ever get scheduled without manual intervention. But as you note, there doesn't seem to be a good, clean alternative in Android.

chenxiaolong commented 1 month ago

Yep, I think the best we can do for the crash scenario is to just move the scheduling to the beginning of doWork() (or try/catch the whole thing).

tmo1 commented 1 month ago

Yep, I think the best we can do for the crash scenario is to just move the scheduling to the beginning of doWork() (or try/catch the whole thing).

I think I'll try the former when I get a chance. I just can't believe that Android is making me reimplement cron, badly :|

Thanks again for all the help.