Logging WorkManager Workers

Question

I am trying to get some logging information on WorkManager Workers that i have running in my app. I am using version 2.4.0-alpha01 which uses the new diagnostics added by the Android Framework Team

https://developer.android.com/jetpack/androidx/releases/work#2.4.0-alpha01

They instructed me to run the following command

adb shell am broadcast -a "androidx.work.diagnostics.REQUEST_DIAGNOSTICS" -p "<your_app_package_name>"

when i executed this command it just echoed

Broadcast completed: result=0 

to the terminal

They then informed me that i should see the diagnostics in logcat by running

adb logcat

I ran that command and the output of the logs look like they are obfuscated and i don't see any logs specific to my Workers.

How do you go about parsing these logs to get information about your WorkManager Workers?

Update

I now see the WorkManager logs because i have added WM- as a search keyword in the logcat.

I have noticed that some of my workers have stopped running and I don't understand why.

These are the logs starting from the last successful worker

2020-04-27 10:52:32.439 com.sampleapp.android.staging.debug D/WM-StopWorkRunnable: StopWorkRunnable for 58c8d95c-4cbc-4a85-aa18-a93e9926019a; Processor.stopWork = false
2020-04-27 10:52:35.304 com.sampleapp.android.staging.debug D/WM-WorkerWrapper: com.sampleapp.android.common.workers.DownloadMediaWorker returned a Success {mOutputData=Data {MEDIA_ITEM_ID : 16503, }} result.
2020-04-27 10:52:35.308 com.sampleapp.android.staging.debug I/WM-WorkerWrapper: Worker result SUCCESS for Work [ id=b892f6fc-79e4-4475-8da6-d151f217bf59, tags={ com.sampleapp.android.common.workers.DownloadMediaWorker, DOWNLOAD_MEDIA_ITEM_16_1_1 } ]
2020-04-27 10:52:35.314 com.sampleapp.android.staging.debug D/WM-Processor: Processor b892f6fc-79e4-4475-8da6-d151f217bf59 executed; reschedule = false
2020-04-27 10:52:35.315 com.sampleapp.android.staging.debug D/WM-GreedyScheduler: Stopping tracking for b892f6fc-79e4-4475-8da6-d151f217bf59
2020-04-27 10:52:35.316 com.sampleapp.android.staging.debug D/WM-WorkConstraintsTrack: Constraints met for 591f9f8f-a938-44ce-962d-5ef952dc01c9
2020-04-27 10:52:35.317 com.sampleapp.android.staging.debug D/WM-WorkConstraintsTrack: Constraints met for 25fc121b-3036-454e-ae89-da6a715ae570
2020-04-27 10:52:35.317 com.sampleapp.android.staging.debug D/WM-WorkConstraintsTrack: Constraints met for 47c4e47a-a66e-49aa-83b8-8670aae4b797
2020-04-27 10:52:35.317 com.sampleapp.android.staging.debug D/WM-WorkConstraintsTrack: Constraints met for 954adf4b-246a-4cff-bcd0-c6a6d6b27e2e
2020-04-27 10:52:35.317 com.sampleapp.android.staging.debug D/WM-WorkConstraintsTrack: Constraints met for e30b4db8-648a-4f55-8cb8-b6a6d098c46a
2020-04-27 10:52:35.317 com.sampleapp.android.staging.debug D/WM-WorkConstraintsTrack: Constraints met for cb1320f6-2510-430f-a400-2b12c85d4a1c
2020-04-27 10:52:35.317 com.sampleapp.android.staging.debug D/WM-WorkConstraintsTrack: Constraints met for b892f6fc-79e4-4475-8da6-d151f217bf59
2020-04-27 10:52:35.317 com.sampleapp.android.staging.debug D/WM-WorkConstraintsTrack: Constraints met for cbbe8de7-be76-4f03-8d26-79bf03af1314
2020-04-27 10:52:35.318 com.sampleapp.android.staging.debug D/WM-GreedyScheduler: Constraints met: Scheduling work ID 591f9f8f-a938-44ce-962d-5ef952dc01c9
2020-04-27 10:52:35.318 com.sampleapp.android.staging.debug D/WM-GreedyScheduler: Constraints met: Scheduling work ID 25fc121b-3036-454e-ae89-da6a715ae570
2020-04-27 10:52:35.318 com.sampleapp.android.staging.debug D/WM-GreedyScheduler: Cancelling work ID b892f6fc-79e4-4475-8da6-d151f217bf59
2020-04-27 10:52:35.318 com.sampleapp.android.staging.debug D/WM-GreedyScheduler: Constraints met: Scheduling work ID 47c4e47a-a66e-49aa-83b8-8670aae4b797
2020-04-27 10:52:35.318 com.sampleapp.android.staging.debug D/WM-GreedyScheduler: Constraints met: Scheduling work ID 954adf4b-246a-4cff-bcd0-c6a6d6b27e2e
2020-04-27 10:52:35.318 com.sampleapp.android.staging.debug D/WM-GreedyScheduler: Constraints met: Scheduling work ID e30b4db8-648a-4f55-8cb8-b6a6d098c46a
2020-04-27 10:52:35.318 com.sampleapp.android.staging.debug D/WM-GreedyScheduler: Constraints met: Scheduling work ID cb1320f6-2510-430f-a400-2b12c85d4a1c
2020-04-27 10:52:35.319 com.sampleapp.android.staging.debug D/WM-GreedyScheduler: Constraints met: Scheduling work ID b892f6fc-79e4-4475-8da6-d151f217bf59
2020-04-27 10:52:35.319 com.sampleapp.android.staging.debug D/WM-GreedyScheduler: Constraints met: Scheduling work ID cbbe8de7-be76-4f03-8d26-79bf03af1314
2020-04-27 10:52:35.319 com.sampleapp.android.staging.debug D/WM-SystemJobService: b892f6fc-79e4-4475-8da6-d151f217bf59 executed on JobScheduler
2020-04-27 10:52:35.320 com.sampleapp.android.staging.debug D/WM-SystemJobService: onStopJob for b892f6fc-79e4-4475-8da6-d151f217bf59
2020-04-27 10:52:35.324 com.sampleapp.android.staging.debug D/WM-Processor: Work 591f9f8f-a938-44ce-962d-5ef952dc01c9 is already enqueued for processing
2020-04-27 10:52:35.324 com.sampleapp.android.staging.debug D/WM-Processor: Work 25fc121b-3036-454e-ae89-da6a715ae570 is already enqueued for processing
2020-04-27 10:52:35.326 com.sampleapp.android.staging.debug D/WM-Processor: Processor stopping background work b892f6fc-79e4-4475-8da6-d151f217bf59
2020-04-27 10:52:35.326 com.sampleapp.android.staging.debug D/WM-Processor: WorkerWrapper could not be found for b892f6fc-79e4-4475-8da6-d151f217bf59
2020-04-27 10:52:35.326 com.sampleapp.android.staging.debug D/WM-StopWorkRunnable: StopWorkRunnable for b892f6fc-79e4-4475-8da6-d151f217bf59; Processor.stopWork = false
2020-04-27 10:52:35.326 com.sampleapp.android.staging.debug D/WM-Processor: Work 47c4e47a-a66e-49aa-83b8-8670aae4b797 is already enqueued for processing
2020-04-27 10:52:35.326 com.sampleapp.android.staging.debug D/WM-Processor: Work 954adf4b-246a-4cff-bcd0-c6a6d6b27e2e is already enqueued for processing
2020-04-27 10:52:35.326 com.sampleapp.android.staging.debug D/WM-Processor: Work e30b4db8-648a-4f55-8cb8-b6a6d098c46a is already enqueued for processing
2020-04-27 10:52:35.327 com.sampleapp.android.staging.debug D/WM-Processor: Work cb1320f6-2510-430f-a400-2b12c85d4a1c is already enqueued for processing
2020-04-27 10:52:35.327 com.sampleapp.android.staging.debug D/WM-Processor: Processor: processing b892f6fc-79e4-4475-8da6-d151f217bf59
2020-04-27 10:52:35.327 com.sampleapp.android.staging.debug D/WM-Processor: Work cbbe8de7-be76-4f03-8d26-79bf03af1314 is already enqueued for processing
2020-04-27 10:52:35.328 com.sampleapp.android.staging.debug D/WM-Processor: Processor stopping background work b892f6fc-79e4-4475-8da6-d151f217bf59
2020-04-27 10:52:35.329 com.sampleapp.android.staging.debug D/WM-WorkerWrapper: Work interrupted for null
2020-04-27 10:52:35.330 com.sampleapp.android.staging.debug D/WM-WorkerWrapper: WorkSpec null is already done. Not interrupting.
2020-04-27 10:52:35.331 com.sampleapp.android.staging.debug D/WM-Processor: WorkerWrapper interrupted for b892f6fc-79e4-4475-8da6-d151f217bf59
2020-04-27 10:52:35.331 com.sampleapp.android.staging.debug D/WM-StopWorkRunnable: StopWorkRunnable for b892f6fc-79e4-4475-8da6-d151f217bf59; Processor.stopWork = true
2020-04-27 10:52:35.331 com.sampleapp.android.staging.debug D/WM-Processor: Processor b892f6fc-79e4-4475-8da6-d151f217bf59 executed; reschedule = false
2020-04-27 10:52:35.331 com.sampleapp.android.staging.debug D/WM-GreedyScheduler: Stopping tracking for b892f6fc-79e4-4475-8da6-d151f217bf59
2020-04-27 10:52:35.332 com.sampleapp.android.staging.debug D/WM-WorkConstraintsTrack: Constraints met for 591f9f8f-a938-44ce-962d-5ef952dc01c9
2020-04-27 10:52:35.332 com.sampleapp.android.staging.debug D/WM-WorkConstraintsTrack: Constraints met for 25fc121b-3036-454e-ae89-da6a715ae570
2020-04-27 10:52:35.332 com.sampleapp.android.staging.debug D/WM-WorkConstraintsTrack: Constraints met for 47c4e47a-a66e-49aa-83b8-8670aae4b797
2020-04-27 10:52:35.332 com.sampleapp.android.staging.debug D/WM-WorkConstraintsTrack: Constraints met for 954adf4b-246a-4cff-bcd0-c6a6d6b27e2e
2020-04-27 10:52:35.332 com.sampleapp.android.staging.debug D/WM-WorkConstraintsTrack: Constraints met for e30b4db8-648a-4f55-8cb8-b6a6d098c46a
2020-04-27 10:52:35.332 com.sampleapp.android.staging.debug D/WM-WorkConstraintsTrack: Constraints met for cb1320f6-2510-430f-a400-2b12c85d4a1c
2020-04-27 10:52:35.332 com.sampleapp.android.staging.debug D/WM-WorkConstraintsTrack: Constraints met for cbbe8de7-be76-4f03-8d26-79bf03af1314
2020-04-27 10:52:35.332 com.sampleapp.android.staging.debug D/WM-GreedyScheduler: Constraints met: Scheduling work ID 591f9f8f-a938-44ce-962d-5ef952dc01c9
2020-04-27 10:52:35.333 com.sampleapp.android.staging.debug D/WM-GreedyScheduler: Constraints met: Scheduling work ID 25fc121b-3036-454e-ae89-da6a715ae570
2020-04-27 10:52:35.333 com.sampleapp.android.staging.debug D/WM-GreedyScheduler: Constraints met: Scheduling work ID 47c4e47a-a66e-49aa-83b8-8670aae4b797
2020-04-27 10:52:35.333 com.sampleapp.android.staging.debug D/WM-GreedyScheduler: Constraints met: Scheduling work ID 954adf4b-246a-4cff-bcd0-c6a6d6b27e2e
2020-04-27 10:52:35.333 com.sampleapp.android.staging.debug D/WM-GreedyScheduler: Constraints met: Scheduling work ID e30b4db8-648a-4f55-8cb8-b6a6d098c46a
2020-04-27 10:52:35.333 com.sampleapp.android.staging.debug D/WM-GreedyScheduler: Constraints met: Scheduling work ID cb1320f6-2510-430f-a400-2b12c85d4a1c
2020-04-27 10:52:35.333 com.sampleapp.android.staging.debug D/WM-GreedyScheduler: Constraints met: Scheduling work ID cbbe8de7-be76-4f03-8d26-79bf03af1314
2020-04-27 10:52:35.340 com.sampleapp.android.staging.debug D/WM-WorkerWrapper: Work interrupted for Work [ id=b892f6fc-79e4-4475-8da6-d151f217bf59, tags={ com.sampleapp.android.common.workers.DownloadMediaWorker, DOWNLOAD_MEDIA_ITEM_16_1_1 } ]
2020-04-27 10:52:35.342 com.sampleapp.android.staging.debug D/WM-Processor: Work 591f9f8f-a938-44ce-962d-5ef952dc01c9 is already enqueued for processing
2020-04-27 10:52:35.342 com.sampleapp.android.staging.debug D/WM-Processor: Work 25fc121b-3036-454e-ae89-da6a715ae570 is already enqueued for processing
2020-04-27 10:52:35.343 com.sampleapp.android.staging.debug D/WM-Processor: Work 47c4e47a-a66e-49aa-83b8-8670aae4b797 is already enqueued for processing
2020-04-27 10:52:35.343 com.sampleapp.android.staging.debug D/WM-Processor: Work 954adf4b-246a-4cff-bcd0-c6a6d6b27e2e is already enqueued for processing
2020-04-27 10:52:35.343 com.sampleapp.android.staging.debug D/WM-Processor: Work e30b4db8-648a-4f55-8cb8-b6a6d098c46a is already enqueued for processing
2020-04-27 10:52:35.343 com.sampleapp.android.staging.debug D/WM-Processor: Work cb1320f6-2510-430f-a400-2b12c85d4a1c is already enqueued for processing
2020-04-27 10:52:35.343 com.sampleapp.android.staging.debug D/WM-Processor: Work cbbe8de7-be76-4f03-8d26-79bf03af1314 is already enqueued for processing
2020-04-27 10:52:35.559 com.sampleapp.android.staging.debug D/WM-NetworkStateTracker: Network capabilities changed: [ Transports: WIFI Capabilities: NOT_METERED&INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VPN&VALIDATED&NOT_ROAMING&FOREGROUND&NOT_CONGESTED&NOT_SUSPENDED LinkUpBandwidth>=1048576Kbps LinkDnBandwidth>=1048576Kbps SignalStrength: -68]
2020-04-27 10:52:56.786 com.sampleapp.android.staging.debug D/WM-NetworkStateTracker: Network capabilities changed: [ Transports: WIFI Capabilities: NOT_METERED&INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VPN&VALIDATED&NOT_ROAMING&FOREGROUND&NOT_CONGESTED&NOT_SUSPENDED LinkUpBandwidth>=1048576Kbps LinkDnBandwidth>=1048576Kbps SignalStrength: -65]
2020-04-27 10:53:09.183 com.sampleapp.android.staging.debug D/WM-NetworkStateTracker: Network capabilities changed: [ Transports: WIFI Capabilities: NOT_METERED&INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VPN&VALIDATED&NOT_ROAMING&FOREGROUND&NOT_CONGESTED&NOT_SUSPENDED LinkUpBandwidth>=1048576Kbps LinkDnBandwidth>=1048576Kbps SignalStrength: -67]
2020-04-27 10:53:18.379 com.sampleapp.android.staging.debug D/WM-NetworkStateTracker: Network capabilities changed: [ Transports: WIFI Capabilities: NOT_METERED&INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VPN&VALIDATED&NOT_ROAMING&FOREGROUND&NOT_CONGESTED&NOT_SUSPENDED LinkUpBandwidth>=1048576Kbps LinkDnBandwidth>=1048576Kbps SignalStrength: -65]
2020-04-27 10:53:27.594 com.sampleapp.android.staging.debug D/WM-NetworkStateTracker: Network capabilities changed: [ Transports: WIFI Capabilities: NOT_METERED&INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VPN&VALIDATED&NOT_ROAMING&FOREGROUND&NOT_CONGESTED&NOT_SUSPENDED LinkUpBandwidth>=1048576Kbps LinkDnBandwidth>=1048576Kbps SignalStrength: -67]
2020-04-27 10:53:30.602 com.sampleapp.android.staging.debug D/WM-NetworkStateTracker: Network capabilities changed: [ Transports: WIFI Capabilities: NOT_METERED&INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VPN&VALIDATED&NOT_ROAMING&FOREGROUND&NOT_CONGESTED&NOT_SUSPENDED LinkUpBandwidth>=1048576Kbps LinkDnBandwidth>=1048576Kbps SignalStrength: -66]
2020-04-27 10:53:58.250 com.sampleapp.android.staging.debug D/WM-NetworkStateTracker: Network capabilities changed: [ Transports: WIFI Capabilities: NOT_METERED&INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VPN&VALIDATED&NOT_ROAMING&FOREGROUND&NOT_CONGESTED&NOT_SUSPENDED LinkUpBandwidth>=1048576Kbps LinkDnBandwidth>=1048576Kbps SignalStrength: -67]
2020-04-27 10:54:01.367 com.sampleapp.android.staging.debug D/WM-NetworkStateTracker: Network capabilities changed: [ Transports: WIFI Capabilities: NOT_METERED&INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VPN&VALIDATED&NOT_ROAMING&FOREGROUND&NOT_CONGESTED&NOT_SUSPENDED LinkUpBandwidth>=1048576Kbps LinkDnBandwidth>=1048576Kbps SignalStrength: -66]
2020-04-27 10:56:10.497 com.sampleapp.android.staging.debug D/WM-NetworkStateTracker: Network capabilities changed: [ Transports: WIFI Capabilities: NOT_METERED&INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VPN&VALIDATED&NOT_ROAMING&FOREGROUND&NOT_CONGESTED&NOT_SUSPENDED LinkUpBandwidth>=1048576Kbps LinkDnBandwidth>=1048576Kbps SignalStrength: -67]
2020-04-27 10:56:13.536 com.sampleapp.android.staging.debug D/WM-NetworkStateTracker: Network capabilities changed: [ Transports: WIFI Capabilities: NOT_METERED&INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VPN&VALIDATED&NOT_ROAMING&FOREGROUND&NOT_CONGESTED&NOT_SUSPENDED LinkUpBandwidth>=1048576Kbps LinkDnBandwidth>=1048576Kbps SignalStrength: -65]

What exactly are these logs saying? Why would my workers stop running?

Answer 1

There are many things that can influence work of the WorkManager. According to logs, it is not happening due to the exceptions that could have been thrown in your workers. It's important to remember that the same code may behave differently on different OEMs as well.

Here are a few things to check out though:

First, WorkManager uses other scheduling mechanisms internally:

• JobScheduler
• FirebaseJobDispatcher
• AlarmManager

All of them have their own constraints. For example, Job Scheduler has 10-minute limit to run its task.

Second is the API of Work Manager itself: if a job with the same name and REPLACE policy is scheduled, current worker stops.

Third - constraints. If the constraints are no longer satisfied, eg issue with network connection, the job will be cancelled.

Forth - it's unlikely in any particular case, but there are bugs everywhere: https://issuetracker.google.com/issues/140055777

Fifth. Most likely, though, worker is stopped due to the Doze mode or othere background work optimizations: https://developer.android.com/training/monitoring-device-state/doze-standby

• Doze mode
• App stand-by buckets
• App background restrictions
• App battery optimization https://issuetracker.google.com/issues/140055777

In order to check out if that is the case, you can make the next trick:

1) Send a Toast message in workers' onStop() call when BuildConfig.DEBUG is true. This way you will notice when a worker gets stopped.

2) Try getting a WakeLock that will prevent your app and phone to get to sleep (only for debug time): https://developer.android.com/training/scheduling/wakelock This way you can check out if the workers are dying in case if the phone is not getting to sleep.

Then, if your experiments show that the worker is dying due to the battery optimizations, you can either get wakelocks for something really important, either simply make your work idempotent and write the workers in a way that it's ok for a worker to be stopped and restarted somewhere in the future. After all, that's the reason why all the restrictions came - we want to save users' batteries.