Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Battery charge limit causes scheduled backups to fail #833

Open
schklom opened this issue Jan 3, 2025 · 9 comments
Open

Battery charge limit causes scheduled backups to fail #833

schklom opened this issue Jan 3, 2025 · 9 comments
Labels
bug help wanted needs info Requires more information from reporter

Comments

@schklom
Copy link

schklom commented Jan 3, 2025 •
edited
Loading

c.f. GrapheneOS/os-issue-tracker#4626

the issue (Charge limit causes bug with Seedvault device backup)

How to reproduce

  1. Enable the charge limit
  2. Plug the phone to charger
  3. (Maybe unnecessary) Go to "Backup scheduling" > enable "Back up only when charging"
  4. Enable "Backup scheduling"
  5. When the scheduled backup happens, the notification "backup failed" happens

Effect

This causes the "backup failed" notification to pop up, and come back whenever it gets dismissed.

Temporary solution

Turn off charge limit, or unplug the phone, or turn off backup scheduling and run backups manually instead.

Originally posted by @schklom in GrapheneOS/os-issue-tracker#4626 (comment)

and the official reply

Needs to be fixed in Seedvault upstream. We're using the standard Android HAL for this.

Originally posted by @thestinger in GrapheneOS/os-issue-tracker#4626 (comment)

EDIT follow-up messages on original issue:

We're planning on replacing Seedvault with an app using a significantly different approach and don't really want to track the issues here.

Originally posted by @thestinger in GrapheneOS/os-issue-tracker#4626 (comment)

There's a standard Pixel HAL feature for setting the charge to limit just to clarify what is meant by that. We're not setting it with the low-level kernel APIs which are not properly supported by the higher level OS. We considered doing it that way to make it more configurable but it's not the right approach without significant further changes.

Originally posted by @thestinger in GrapheneOS/os-issue-tracker#4626 (comment)
@schklom schklom mentioned this issue Jan 3, 2025
Closed
@grote
Copy link
Collaborator

grote commented Jan 3, 2025 •
edited
Loading

Thanks for the report! Would it be possible to export a log with Seedvault (main menu -> 3 dots -> expert settings -> export log) soon after the backup failed?

@grote grote added the needs info Requires more information from reporter label Jan 3, 2025
@schklom
Copy link
Author

schklom commented Jan 3, 2025

Sure! I'll do this in about 20 hours when the next scheduled backup triggers

@grote
Copy link
Collaborator

grote commented Jan 6, 2025

any news?

@schklom
Copy link
Author

schklom commented Jan 6, 2025

seedvault-15-5.1-1736003064071.txt
I let the backup fail (only happen with scheduled backup, not manual), then dismissed the notification about 5 times, then found this file a minute later

@grote
Copy link
Collaborator

grote commented Jan 6, 2025

Thanks for the log!

Looks like WorkManager is running amok. It starts and stops work in a loop. I've seen something similar in another project and reported it to Google. However, I don't know how to solve this without their help. Suggestions welcome.

01-04 16:04:32.441 16200 16200 D WM-Processor: Processor 6057ac7f-2500-4cf7-868a-1928c388c10e executed; reschedule = true
01-04 16:04:32.441 16200 16200 D WM-SystemJobService: 6057ac7f-2500-4cf7-868a-1928c388c10e executed on JobScheduler
01-04 16:04:32.441 16200 16223 D WM-BrdcstRcvrCnstrntTrc: BatteryChargingTracker: unregistering receiver
01-04 16:04:32.469 16200 16223 D WM-GreedyScheduler: Cancelling work ID 6057ac7f-2500-4cf7-868a-1928c388c10e
01-04 16:04:32.470 16200 16223 D WM-SystemJobScheduler: Scheduling work ID 6057ac7f-2500-4cf7-868a-1928c388c10eJob ID 2024
01-04 16:04:32.476 16200 16200 D WM-SystemJobService: onStartJob for WorkGenerationalId(workSpecId=6057ac7f-2500-4cf7-868a-1928c388c10e, generation=0)
01-04 16:04:32.480 16200 16223 D WM-Processor: Processor: processing WorkGenerationalId(workSpecId=6057ac7f-2500-4cf7-868a-1928c388c10e, generation=0)
01-04 16:04:32.480 16200 16200 I BackupStateManager: appBackupRunning: false, filesBackupRunning: false, appBackupWorker: ENQUEUED
01-04 16:04:32.484 16200 16200 D WM-WorkerWrapper: Starting work for com.stevesoltys.seedvault.worker.AppBackupWorker
01-04 16:04:32.484 16200 18193 I AppBackupWorker: Start worker  com.stevesoltys.seedvault.worker.AppBackupWorker@40f71e7 (6057ac7f-2500-4cf7-868a-1928c388c10e)
01-04 16:04:32.488 16200 16200 I BackupStateManager: appBackupRunning: false, filesBackupRunning: false, appBackupWorker: RUNNING
01-04 16:04:32.490 16200 17286 I BackupStateManager: pruneBackupWorker: SUCCEEDED, appCheckerWorker: null
01-04 16:04:32.492 16200 16224 I WM-Processor: Moving WorkSpec (6057ac7f-2500-4cf7-868a-1928c388c10e) to the foreground
01-04 16:04:32.495  1357  1497 I ActivityManager: Background started FGS: Allowed [callingPackage: com.stevesoltys.seedvault; callingUid: 10040; uidState: TOP ; uidBFSL: [BFSL]; intent: Intent { act=ACTION_START_FOREGROUND cmp=com.stevesoltys.seedvault/androidx.work.impl.foreground.SystemForegroundService (has extras) }; code:PROC_STATE_TOP; tempAllowListReason:<,reasonCode:SYSTEM_ALLOW_LISTED,duration:9223372036854775807,callingUid:-1>; targetSdkVersion:35; callerTargetSdkVersion:35; startForegroundCount:0; bindFromPackage:null: isBindService:false]
01-04 16:04:32.498 16200 16200 I WM-SystemFgDispatcher: Started foreground service Intent { act=ACTION_START_FOREGROUND cmp=com.stevesoltys.seedvault/androidx.work.impl.foreground.SystemForegroundService (has extras) }
01-04 16:04:32.498 16200 16200 D WM-SystemFgDispatcher: Notifying with (id:1, workSpecId: 6057ac7f-2500-4cf7-868a-1928c388c10e, notificationType :1)
01-04 16:04:32.499  1357 10077 I ActivityManager: Background started FGS: Allowed [callingPackage: com.stevesoltys.seedvault; callingUid: 10040; uidState: TOP ; uidBFSL: [BFSL]; intent: Intent { act=ACTION_START_FOREGROUND cmp=com.stevesoltys.seedvault/androidx.work.impl.foreground.SystemForegroundService }; code:PROC_STATE_TOP; tempAllowListReason:<,reasonCode:SYSTEM_ALLOW_LISTED,duration:9223372036854775807,callingUid:-1>; targetSdkVersion:35; callerTargetSdkVersion:35; startForegroundCount:0; bindFromPackage:null: isBindService:false]
01-04 16:04:32.499  1357 10077 W ForegroundServiceTypeLoggerModule: Foreground service start for UID: 10040 does not have any types
01-04 16:04:32.505 16200 16200 D WM-SystemFgDispatcher: Notifying with (id:1, workSpecId: 6057ac7f-2500-4cf7-868a-1928c388c10e, notificationType :1)
01-04 16:04:32.506 16200 16238 D a.g.s.c.b.s.SafBackend: [DefaultDispatcher-worker-2] getFreeSpace()
01-04 16:04:32.506 16200 16238 I AppBackupWorker: freeSpace: null
01-04 16:04:32.506 16200 16238 I AppBackupWorker: Initializing backup info...
01-04 16:04:32.506 16200 16238 I c.s.s.r.AppBackupManager: [DefaultDispatcher-worker-2] Loading existing snapshots and blobs...
01-04 16:04:32.506 16200 16238 D a.g.s.c.b.s.SafBackend: [DefaultDispatcher-worker-2] list(TopLevelFolder(name=9e745c5f20b0b93761cbf7f63ab6819c796b8ce4cfa1c4bd30833a51976f60a3), [Blob, Snapshot])
01-04 16:04:32.506 16200 16224 D WM-ConstraintTracker: BatteryChargingTracker: initial state = false
01-04 16:04:32.506 16200 16224 D WM-BrdcstRcvrCnstrntTrc: BatteryChargingTracker: registering receiver
01-04 16:04:32.508 16200 16224 D WM-SystemFgDispatcher: Constraints unmet for WorkSpec 6057ac7f-2500-4cf7-868a-1928c388c10e
01-04 16:04:32.510  1357  1497 I ActivityManager: Background started FGS: Allowed [callingPackage: com.stevesoltys.seedvault; callingUid: 10040; uidState: TOP ; uidBFSL: [BFSL]; intent: Intent { act=ACTION_START_FOREGROUND cmp=com.stevesoltys.seedvault/androidx.work.impl.foreground.SystemForegroundService }; code:PROC_STATE_TOP; tempAllowListReason:<,reasonCode:SYSTEM_ALLOW_LISTED,duration:9223372036854775807,callingUid:-1>; targetSdkVersion:35; callerTargetSdkVersion:35; startForegroundCount:1; bindFromPackage:null: isBindService:false]
01-04 16:04:32.510 16200 16224 D WM-Processor: WorkerWrapper interrupted for 6057ac7f-2500-4cf7-868a-1928c388c10e
01-04 16:04:32.510 16200 16224 D WM-StopWorkRunnable: StopWorkRunnable for 6057ac7f-2500-4cf7-868a-1928c388c10e; Processor.stopWork = true
01-04 16:04:32.512 16200 16200 I WM-SystemFgDispatcher: Stopping foreground service
01-04 16:04:32.512 16200 16200 D WM-SystemFgService: Shutting down.
01-04 16:04:32.512  1357  2247 D ActivityManager: Stop FGS timeout: ServiceRecord{3f07bfb u0 com.stevesoltys.seedvault/androidx.work.impl.foreground.SystemForegroundService c:com.stevesoltys.seedvault}
01-04 16:04:32.513  1357  2247 W ForegroundServiceTypeLoggerModule: FGS stop call for: 10040 has no types!
01-04 16:04:32.515 16200 16224 I WM-WorkerWrapper: Work [ id=6057ac7f-2500-4cf7-868a-1928c388c10e, tags={ com.stevesoltys.seedvault.worker.AppBackupWorker } ] was cancelled
01-04 16:04:32.515 16200 16224 I WM-WorkerWrapper: androidx.work.impl.WorkerStoppedException
01-04 16:04:32.515 16200 16224 I WM-WorkerWrapper: 	at androidx.work.impl.WorkerWrapper.interrupt(WorkerWrapper.kt:348)
01-04 16:04:32.515 16200 16224 I WM-WorkerWrapper: 	at androidx.work.impl.Processor.interrupt(Processor.java:439)
01-04 16:04:32.515 16200 16224 I WM-WorkerWrapper: 	at androidx.work.impl.Processor.stopForegroundWork(Processor.java:227)
01-04 16:04:32.515 16200 16224 I WM-WorkerWrapper: 	at androidx.work.impl.utils.StopWorkRunnable.run(StopWorkRunnable.kt:45)
01-04 16:04:32.515 16200 16224 I WM-WorkerWrapper: 	at androidx.work.impl.utils.SerialExecutorImpl$Task.run(SerialExecutorImpl.java:96)
01-04 16:04:32.515 16200 16224 I WM-WorkerWrapper: 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
01-04 16:04:32.515 16200 16224 I WM-WorkerWrapper: 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:644)
01-04 16:04:32.515 16200 16224 I WM-WorkerWrapper: 	at java.lang.Thread.run(Thread.java:1117)
01-04 16:04:32.515 16200 16224 D WM-WorkerWrapper: Status for 6057ac7f-2500-4cf7-868a-1928c388c10e is RUNNING; not doing any work and rescheduling for later execution
01-04 16:04:32.516 16200 16200 D WM-Processor: Processor 6057ac7f-2500-4cf7-868a-1928c388c10e executed; reschedule = true

Later, the log also shows that you run into #828

Is it possible to disable the charging constraint and see if this helps?

@schklom
Copy link
Author

schklom commented Jan 6, 2025

Is it possible to disable the charging constraint and see if this helps?

Sure, I will test it out tomorrow after triggering a failure, and report back

@schklom
Copy link
Author

schklom commented Jan 9, 2025

Finally tested it: disabling the charging constraint solves the bug

@grote
Copy link
Collaborator

grote commented Jan 9, 2025

Good to know that the workaround exists, but other than that I am out of ideas on how to fix the issue on our side. I reported the looping from your log to the same Google ticket, but no answer so far.

@schklom
Copy link
Author

schklom commented Jan 9, 2025

Well, at least now Google knows and might fix it. Thanks for reporting it, I guess we just wait for now.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug help wanted needs info Requires more information from reporter
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@grote @schklom