IssueTracker

Found the issue, ugh

Noticed that when I do the following:
transaction.addToBackStack(null)

When adding a Fragment with ViewPager2, the above issue occurs, although, idk if it's becaugh of gcFragments() anymore.

As soon as I un-comment that line, the issue disappears.

https://github.com/PenguinDan/ViewPagerCrash

Is the Sample application, to reproduce, move back really fast between page 2 -> 1 and vice versa (they are bottom buttons) a couple times.
Wait a couple seconds and page 1 (the black page) should turn white meaning the Fragment has been removed.

As soon as you comment line 40 on MainActivity, and attempt again, the error does not persist

Woops, sorry, If you guys had the previous ViewPagerCrash test app, I forgot to push (was exhasuted after debugging) I pushed one more time for the latest reproducible code

We'll have a look, thanks for reporting and repro steps / sample app. Stay tuned for updates on this issue.

Got to debug this now. Your sample indeed showcases an issue, so thanks for reporting and for the sample!

`transaction.addToBackStack(null)` adds the Fragment replacement transaction to the back stack, so you can go back to the previous state with the back button. Is that what you were looking to achieve? You said it works without it, which might help in the meantime.

Would you mind describing the use-case, so I better understand what you're trying to achieve? E.g. in the example, by switching between buttons 1 and 2 at some point you achieve multiple stack entries going back to the ViewPager2 Fragment.

Mostly for my notes, but the trace below explains what happens. Still need to work out why.

We have 5 instances of FragmentStateAdapter below.
Notice how in lines 36-39 4 different instances of FragmentStateAdapter perform a scheduled gc (after grace period expires).
Those don't have the Fragments bound to their ViewHolders as those were removed: lines  8, 16, 24, 32.

At the same time, com.test.myapplication.VPAdapter.createFragment(ViewPagerFragment.kt:161) only gets called once, so presumably all 5 have a reference to that same Fragment.

Needs more investigation as looks fishy.

     1  {FragmentStateAdapter@11,288}.mItemIdToViewHolder will be modified at FragmentStateAdapter.<init>(FragmentStateAdapter.java:85). Current value = 'null'. New value = 'instance of androidx.collection.LongSparseArray(id=11289)'
     2  {FragmentStateAdapter@11,288}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.itemForViewHolder(FragmentStateAdapter.java:234)
     3  {FragmentStateAdapter@11,288}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.onBindViewHolder(FragmentStateAdapter.java:174)
     4  {FragmentStateAdapter@11,288}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.itemForViewHolder(FragmentStateAdapter.java:234)
     5  {FragmentStateAdapter@11,288}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.itemForViewHolder(FragmentStateAdapter.java:235)
     6  {FragmentStateAdapter@11,288}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.itemForViewHolder(FragmentStateAdapter.java:240)
     7  {FragmentStateAdapter@11,288}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.itemForViewHolder(FragmentStateAdapter.java:234)
     8  {FragmentStateAdapter@11,288}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.onViewRecycled(FragmentStateAdapter.java:391)
     9  {FragmentStateAdapter@11,306}.mItemIdToViewHolder will be modified at FragmentStateAdapter.<init>(FragmentStateAdapter.java:85). Current value = 'null'. New value = 'instance of androidx.collection.LongSparseArray(id=11307)'
    10  {FragmentStateAdapter@11,306}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.itemForViewHolder(FragmentStateAdapter.java:234)
    11  {FragmentStateAdapter@11,306}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.onBindViewHolder(FragmentStateAdapter.java:174)
    12  {FragmentStateAdapter@11,306}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.itemForViewHolder(FragmentStateAdapter.java:234)
    13  {FragmentStateAdapter@11,306}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.itemForViewHolder(FragmentStateAdapter.java:235)
    14  {FragmentStateAdapter@11,306}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.itemForViewHolder(FragmentStateAdapter.java:240)
    15  {FragmentStateAdapter@11,306}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.itemForViewHolder(FragmentStateAdapter.java:234)
    16  {FragmentStateAdapter@11,306}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.onViewRecycled(FragmentStateAdapter.java:391)
    17  {FragmentStateAdapter@11,313}.mItemIdToViewHolder will be modified at FragmentStateAdapter.<init>(FragmentStateAdapter.java:85). Current value = 'null'. New value = 'instance of androidx.collection.LongSparseArray(id=11314)'
    18  {FragmentStateAdapter@11,313}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.itemForViewHolder(FragmentStateAdapter.java:234)
    19  {FragmentStateAdapter@11,313}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.onBindViewHolder(FragmentStateAdapter.java:174)
    20  {FragmentStateAdapter@11,313}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.itemForViewHolder(FragmentStateAdapter.java:234)
    21  {FragmentStateAdapter@11,313}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.itemForViewHolder(FragmentStateAdapter.java:235)
    22  {FragmentStateAdapter@11,313}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.itemForViewHolder(FragmentStateAdapter.java:240)
    23  {FragmentStateAdapter@11,313}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.itemForViewHolder(FragmentStateAdapter.java:234)
    24  {FragmentStateAdapter@11,313}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.onViewRecycled(FragmentStateAdapter.java:391)
    25  {FragmentStateAdapter@11,315}.mItemIdToViewHolder will be modified at FragmentStateAdapter.<init>(FragmentStateAdapter.java:85). Current value = 'null'. New value = 'instance of androidx.collection.LongSparseArray(id=11316)'
    26  {FragmentStateAdapter@11,315}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.itemForViewHolder(FragmentStateAdapter.java:234)
    27  {FragmentStateAdapter@11,315}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.onBindViewHolder(FragmentStateAdapter.java:174)
    28  {FragmentStateAdapter@11,315}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.itemForViewHolder(FragmentStateAdapter.java:234)
    29  {FragmentStateAdapter@11,315}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.itemForViewHolder(FragmentStateAdapter.java:235)
    30  {FragmentStateAdapter@11,315}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.itemForViewHolder(FragmentStateAdapter.java:240)
    31  {FragmentStateAdapter@11,315}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.itemForViewHolder(FragmentStateAdapter.java:234)
    32  {FragmentStateAdapter@11,315}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.onViewRecycled(FragmentStateAdapter.java:391)
    33  {FragmentStateAdapter@11,317}.mItemIdToViewHolder will be modified at FragmentStateAdapter.<init>(FragmentStateAdapter.java:85). Current value = 'null'. New value = 'instance of androidx.collection.LongSparseArray(id=11318)'
    34  {FragmentStateAdapter@11,317}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.itemForViewHolder(FragmentStateAdapter.java:234)
    35  {FragmentStateAdapter@11,317}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.onBindViewHolder(FragmentStateAdapter.java:174)
    36  {FragmentStateAdapter@11,306}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.gcFragments(FragmentStateAdapter.java:221)
    37  {FragmentStateAdapter@11,313}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.gcFragments(FragmentStateAdapter.java:221)
    38  {FragmentStateAdapter@11,315}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.gcFragments(FragmentStateAdapter.java:221)
    39  {FragmentStateAdapter@11,317}.mItemIdToViewHolder will be accessed at FragmentStateAdapter.gcFragments(FragmentStateAdapter.java:221)

Pausing the investigation for now until we better understand the use-case -- questions in comment#6

Yes, completely correct that I am attempting to use the back pressed implementation but also a bottom navigation implementation to switch to and from Fragments.

Currently the app that I am trying to make contains multiple Fragments with and without ViewPager2's accessible through a bottom navigation set of buttons. Through simple usage of moving to and from my ViewPager2 Fragments, I would see random instances of child Fragments disappearing from them.

I'd rather like to keep the "addToBackStack(..)" to rewind through fragment transactions. Will definitely look further into it also from the above mentioned logs.

Thanks for clarifying, I will investigate further.

Following on the logs above, I suspect that each instance of FragmentStateAdapter gets access to that one BaseFragment in FragmentStateAdapter::restoreState (restore state called on each stack entry).
Making sure each ViewPagerFragment instance only gets access to its own state (so the state is not shared between them) should eliminate this issue.

Not sure where the problem lies yet, whether in ViewPager2's interaction with the state saving stack, or in the sample app, so continuing to investigate.

Yeah.. I have no clue what's going on, spending too much time debugging. I am planning to attach LifecycleObserver to my ViewHolder's so they act like Fragments.

From the evidence above, I am pretty sure it should not affect ViewHolder pattern but never know. Would love to know what was happening though if you come across a solution.

Looks like the following is happening in the sample:
- the same instance of ViewPagerFragment is being used for various back-stack entries
- multiple instances of FragmentStateAdapter are being created at each ViewPagerFragment view inflation, and each has their post-grace-period gcFragments() scheduled
- the same page Fragment instance reference is passed to all FragmentStateAdapter instances via restoreState, but can only be bound to one ViewHolder (the current visible one)
- once grace-period ends in non-visible FragmentStateAdapter instances, they see nothing is bound to their ViewHolders and garbage-collect the page Fragment

I will look further into the correct solution, potentially cancelling gcFragments() if a FragmentStateAdapter gets detached from a ViewPager2 (e.g. at ViewPagerFragment view destruction).
This would require a code, change, though, so for now, you can probably work around this by not re-using ViewPagerFragment instances, but creating a new one each time you add it to the stack. There might be a need for passing relevant state, e.g. current page.

Raw debugging notes below in case helpful. I reproduced the issue by switching multiple times between buttons 1 and 2.

***

# how many adapter instances exist

️$ cat ff2  | grep -E "FragmentStateAdapter@[^\}]+" -o | sort -u
FragmentStateAdapter@5,446
FragmentStateAdapter@5,474
FragmentStateAdapter@5,484

# how many adapter instances get their state restored

️$ cat ff2 | grep restoreState | grep -E "FragmentStateAdapter@[^\}]+" -o | sort -u
FragmentStateAdapter@5,474
FragmentStateAdapter@5,484

# where are Fragment pages created

️$ cat ff2 | grep createFragment -C1
{androidx.viewpager2.adapter.FragmentStateAdapter@5,446}.mFragments will be accessed at androidx.viewpager2.adapter.FragmentStateAdapter.ensureFragment(FragmentStateAdapter.java:248)
Breakpoint reached at com.test.myapplication.VPAdapter.createFragment(ViewPagerFragment.kt:161)
{androidx.viewpager2.adapter.FragmentStateAdapter@5,446}.mFragments will be accessed at androidx.viewpager2.adapter.FragmentStateAdapter.ensureFragment(FragmentStateAdapter.java:252)

# confirming that instance 446 is the only adapter creating the views; others are getting it from previously restored state
# for reference, FragmentStateAdapter.java:248 = "if (!mFragments.containsKey(itemId)) {"
# for reference, FragmentStateAdapter.java:252 = "mFragments.put(itemId, newFragment);"

️$ cat ff2 | grep ensureFragment | sort
{androidx.viewpager2.adapter.FragmentStateAdapter@5,446}.mFragments will be accessed at androidx.viewpager2.adapter.FragmentStateAdapter.ensureFragment(FragmentStateAdapter.java:248)
{androidx.viewpager2.adapter.FragmentStateAdapter@5,446}.mFragments will be accessed at androidx.viewpager2.adapter.FragmentStateAdapter.ensureFragment(FragmentStateAdapter.java:252)
{androidx.viewpager2.adapter.FragmentStateAdapter@5,474}.mFragments will be accessed at androidx.viewpager2.adapter.FragmentStateAdapter.ensureFragment(FragmentStateAdapter.java:248)
{androidx.viewpager2.adapter.FragmentStateAdapter@5,484}.mFragments will be accessed at androidx.viewpager2.adapter.FragmentStateAdapter.ensureFragment(FragmentStateAdapter.java:248)

# where is the state with a page Fragment reference coming from

Breakpoint reached
          at androidx.viewpager2.adapter.FragmentStateAdapter.restoreState(FragmentStateAdapter.java:515)
          at androidx.viewpager2.widget.ViewPager2.restorePendingState(ViewPager2.java:337)
          at androidx.viewpager2.widget.ViewPager2.dispatchRestoreInstanceState(ViewPager2.java:362)
          at android.view.View.restoreHierarchyState(View.java:17684)
          at androidx.fragment.app.Fragment.restoreViewState(Fragment.java:539)
          at androidx.fragment.app.FragmentManagerImpl.moveToState(FragmentManagerImpl.java:907)
          at androidx.fragment.app.FragmentManagerImpl.moveFragmentToExpectedState(FragmentManagerImpl.java:1238)
          at androidx.fragment.app.FragmentManagerImpl.moveToState(FragmentManagerImpl.java:1303)
          at androidx.fragment.app.BackStackRecord.executeOps(BackStackRecord.java:439)
          at androidx.fragment.app.FragmentManagerImpl.executeOps(FragmentManagerImpl.java:2076)
          at androidx.fragment.app.FragmentManagerImpl.executeOpsTogether(FragmentManagerImpl.java:1866)
          at androidx.fragment.app.FragmentManagerImpl.removeRedundantOperationsAndExecute(FragmentManagerImpl.java:1821)
          at androidx.fragment.app.FragmentManagerImpl.execPendingActions(FragmentManagerImpl.java:1727)
          at androidx.fragment.app.FragmentManagerImpl$2.run(FragmentManagerImpl.java:150)
          at android.os.Handler.handleCallback(Handler.java:790)
          at android.os.Handler.dispatchMessage(Handler.java:99)
          at android.os.Looper.loop(Looper.java:164)
          at android.app.ActivityThread.main(ActivityThread.java:6494)
          at java.lang.reflect.Method.invoke(Method.java:-1)
          at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:438)
          at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:807)

# how many Fragment instances go through restoreViewState

️$ cat ff4 | grep "restoreViewState. fragment="
restoreViewState: fragment=ViewPagerFragment{d4490de (a6cfe7d3-5376-4015-8357-2408442116ee) id=0x7f070076 Frag1}
restoreViewState: fragment=BaseFragment{de52066 (f5afa133-40d7-45c1-8193-6ce2d4cb5489) f0}
restoreViewState: fragment=BaseFragment{de52066 (f5afa133-40d7-45c1-8193-6ce2d4cb5489) f0}
restoreViewState: fragment=ViewPagerFragment{d4490de (a6cfe7d3-5376-4015-8357-2408442116ee) id=0x7f070076 Frag1}
restoreViewState: fragment=BaseFragment{de52066 (f5afa133-40d7-45c1-8193-6ce2d4cb5489) f0}
restoreViewState: fragment=ViewPagerFragment{d4490de (a6cfe7d3-5376-4015-8357-2408442116ee) id=0x7f070076 Frag1}

# where are ViewPagerFragment instances created in the sample
    ```
    var fragment: Fragment? = supportFragmentManager.findFragmentByTag("Frag$fragmentToOpen")
    if(fragment == null) {
        fragment = when(fragmentToOpen) {
            1 -> ViewPagerFragment()
            2 -> BlankFragment()
            else -> throw IllegalArgumentException()
        }
    }
    ```

Thanks for the suggestion above, creating a new Fragment every time definitely fixes the problem albeit some very ugly code implementation and hacks I had to write to do some state saving in my code (since ViewModels are attached to a specific Fragment instance), my subsequent fragments also need to do some ugly state saving (playing media).

Looking forward to erasing all of this ugly code on next update!

For anybody who has the same exact problem, page state saving works for me in the following manner:

        binding.gamePagerRoot.apply {
            // Set the Adapter for our Fragment
            adapter = gamePagerAdapter

            // Do not allow user touch for this ViewPager2 to affect its scroll, should only be scrolled programmatically
            isUserInputEnabled = false

            // Set the Page Transformation
            setPageTransformer(genStackedPageTransformer2())

            // Listen to page change calbacks
            registerOnPageChangeCallback(onPageChangeCallback)

            // Customize the RecyclerView child
            val recyclerView = getChildAt(0) as RecyclerView
            // Remove the overscroll shaddow
            recyclerView.overScrollMode = RecyclerView.OVER_SCROLL_NEVER
            // Allow nested scrolling
            recyclerView.isNestedScrollingEnabled = true

            // If we are on a different page as specified by our ViewModel, make sure to scroll to the page instantly (no animation)
            if(gamePagerVM?.gamePageIds?.size ?: 1 > 1) {
                recyclerView.viewTreeObserver.addOnGlobalLayoutListener(object: ViewTreeObserver.OnGlobalLayoutListener{
                    override fun onGlobalLayout() {
                        if(recyclerView.childCount >= gamePagerVM?.currPage ?: 0) {
                            viewTreeObserver.removeOnGlobalLayoutListener(this)
                            // If the current page is not 0, set the current page
                            setCurrentItem(gamePagerVM?.currPage ?: 0, false)
                        }
                    }
                })
            }
        }

Project: platform/frameworks/support
Branch: androidx-master-dev

commit 7166ba571d594baa9016e02c3b5fe967da0b8ec0
Author: Jakub Gielzak <jgielzak@google.com>
Date:   Tue Aug 27 16:20:54 2019

    Fix for FragmentStateAdapter#gcFragments()
   
    Fix for an issue with FragmentStateAdapter garbage collection mechanism.
   
    The bug manifested itself in the following scenario:
    - ViewPager2 host Fragment view recreated 3+ times in a window < 10s,
    - Host Fragment instances added to the back stack,
    - ViewPager2 adapter set to null in onViewDestoyed (too late as view
      state already saved, but affecting PageFragment book-keeping).
   
    The fix adds another criteria to gcFragments() in case a
    PageFragment instance gets taken over by a later created instance of
    FragmentStateAdapter.
   
    Bug: 139095195
    Test: ./gradlew viewpager2:connectedCheck
   
    Change-Id: If42bc4e65e8fe52cc0dcd9bbf67a0c55d3c535b1

A       viewpager2/src/androidTest/java/androidx/viewpager2/widget/HostFragmentBackStackTest.kt
M       viewpager2/src/main/java/androidx/viewpager2/adapter/FragmentStateAdapter.java

https://android-review.googlesource.com/1108545
https://goto.google.com/android-sha1/7166ba571d594baa9016e02c3b5fe967da0b8ec0

Project: platform/frameworks/support
Branch: androidx-master-dev

commit 39daf73f75d04b1ba52b007781355595430f8dab
Author: Jakub Gielzak <jgielzak@google.com>
Date:   Tue Aug 27 16:20:16 2019

    Made test FragmentAdapter more flexible.
   
    Needed for the next CL.
   
    Bug: 139095195
    Test: ./gradlew viewpager2:connectedCheck
   
    Change-Id: I3aa4b8a131d3d7bca248f94641c5ee643c6f1819

M       viewpager2/src/androidTest/java/androidx/viewpager2/widget/BaseTest.kt
M       viewpager2/src/androidTest/java/androidx/viewpager2/widget/swipe/FragmentAdapter.kt

https://android-review.googlesource.com/1108544
https://goto.google.com/android-sha1/39daf73f75d04b1ba52b007781355595430f8dab

beta04 with a fix for this was released today

I'm attaching some logs which may be of interest.  It includes the extra WorkManager logging you describe above, plus some random bits of logging from my own code (though I've removed quite a bit to avoid overkill here).  I've added some annotations to note where the user did various actions (I'm guessing a little but fairly sure) to add some context.

The interest bit starts from "01-29 20:51:44.715"

I looked at the logs, and there are a lot of Worker cancellations happening. Are you explicitly cancelling work or using Existing{Periodic}WorkPolicy.REPLACE ?
Can you send us a trimmed down sample of how Workers are being enqueued for your app ?

Sorry, I see that you are using unique work. Looking into this further.

I don't think I'm doing much out of the ordinary when scheduling the periodic work... basically as follows (leaving in the logging that corresponds to what you see in the logcat, and removing some of the value fetching logic, e.g. fetching values from SharedPrefs etc).  Entry point is e.g. schedulePeriodicWork(1234, "some-trigger");

    static void schedulePeriodicWork(int appWidgetId, String trigger) {
        Log.d(TAG, "schedulePeriodicWork for " + appWidgetId);
        String name = getPeriodicName(appWidgetId);
        long interval = getInterval();
        Constraints constraints = getConstraints("periodic");
        Data inputData = getPeriodicInputData(appWidgetId, trigger);
        PeriodicWorkRequest workRequest = getPeriodicWorkRequest(appWidgetId, interval, constraints, inputData);
        WorkManager workManager = WorkManager.getInstance();
        workManager.enqueueUniquePeriodicWork(name, ExistingPeriodicWorkPolicy.REPLACE, workRequest);
    }

    private static String getPeriodicName(int appWidgetId) {
        return "periodic-" + appWidgetId;
    }

    private static long getInterval() {
        return 15 * 60 * 1000;
    }

    private static Constraints getConstraints(String method) {
        Log.d(TAG, "creating Constraints for " + method);
        Constraints.Builder constraintsBuilder = new Constraints.Builder();
        Log.d(TAG, "adding network constraint");
        constraintsBuilder.setRequiredNetworkType(NetworkType.CONNECTED);
        return constraintsBuilder.build();
    }

    private static PeriodicWorkRequest getPeriodicWorkRequest(int appWidgetId, long interval, Constraints constraints, Data inputData) {
        String workTag = getWorkTag(appWidgetId);
        Log.d(TAG, "creating PeriodicWorkRequest with tag " + workTag + " and with interval " + interval + " ms");
        PeriodicWorkRequest.Builder workRequestBuilder = new PeriodicWorkRequest.Builder(MeteogramWorker.class, interval, TimeUnit.MILLISECONDS);
        workRequestBuilder.setConstraints(constraints);
        workRequestBuilder.setInputData(inputData);
        workRequestBuilder.addTag(workTag);
        workRequestBuilder.addTag(PERIODIC);
        return workRequestBuilder.build();
    }

    private static Data getPeriodicInputData(int appWidgetId, String trigger) {
        Log.d(TAG, "creating Data");
        Data.Builder dataBuilder = new Data.Builder();
        dataBuilder.putInt(AppWidgetManager.EXTRA_APPWIDGET_ID, appWidgetId);
        dataBuilder.putString(trigger);
        dataBuilder.putString("method", "periodic");
        return dataBuilder.build();
    }

    private static String getWorkTag(int appWidgetId) {
        return "widget-" + appWidgetId;
    }

Presumably there is some significance in the log entries around the time that the 15 min periodic work is due to run -- if there had been network available -- i.e. around 21:07 ?  i.e. the ones that refer to failed linking and resolving of work-related classes?  Examples:

01-29 21:07:01.245 W/dalvikvm(29185): Unable to resolve superclass of Landroidx/work/impl/background/systemjob/SystemJobService; (90)
01-29 21:07:01.245 W/dalvikvm(29185): Link of class 'Landroidx/work/impl/background/systemjob/SystemJobService;' failed
01-29 21:07:01.245 E/dalvikvm(29185): Could not find class 'androidx.work.impl.background.systemjob.SystemJobService', referenced from method androidx.work.impl.Schedulers.createBestAvailableBackgroundScheduler
01-29 21:07:01.245 W/dalvikvm(29185): VFY: unable to resolve const-class 2971 (Landroidx/work/impl/background/systemjob/SystemJobService;) in Landroidx/work/impl/Schedulers;
01-29 21:07:01.345 W/dalvikvm(29185): Unable to resolve superclass of Landroidx/work/impl/constraints/trackers/NetworkStateTracker$NetworkStateCallback; (341)
01-29 21:07:01.345 W/dalvikvm(29185): Link of class 'Landroidx/work/impl/constraints/trackers/NetworkStateTracker$NetworkStateCallback;' failed
01-29 21:07:01.350 E/dalvikvm(29185): Could not find class 'androidx.work.impl.constraints.trackers.NetworkStateTracker$NetworkStateCallback', referenced from method androidx.work.impl.constraints.trackers.NetworkStateTracker.<init>
01-29 21:07:01.350 W/dalvikvm(29185): VFY: unable to resolve new-instance 2994 (Landroidx/work/impl/constraints/trackers/NetworkStateTracker$NetworkStateCallback;) in Landroidx/work/impl/constraints/trackers/NetworkStateTracker;
01-29 21:07:01.355 I/dalvikvm(29185): Could not find method android.net.ConnectivityManager.getActiveNetwork, referenced from method androidx.work.impl.constraints.trackers.NetworkStateTracker.isActiveNetworkValidated
01-29 21:07:01.355 W/dalvikvm(29185): VFY: unable to resolve virtual method 1865: Landroid/net/ConnectivityManager;.getActiveNetwork ()Landroid/net/Network;
01-29 21:07:01.355 D/dalvikvm(29185): VFY: replacing opcode 0x6e at 0x000a
01-29 21:07:01.360 W/dalvikvm(29185): Unable to resolve superclass of Landroidx/work/impl/constraints/trackers/NetworkStateTracker$NetworkStateCallback; (341)
01-29 21:07:01.360 W/dalvikvm(29185): Link of class 'Landroidx/work/impl/constraints/trackers/NetworkStateTracker$NetworkStateCallback;' failed
01-29 21:07:01.360 I/dalvikvm(29185): Could not find method android.net.ConnectivityManager.registerDefaultNetworkCallback, referenced from method androidx.work.impl.constraints.trackers.NetworkStateTracker.startTracking
01-29 21:07:01.360 W/dalvikvm(29185): VFY: unable to resolve virtual method 1871: Landroid/net/ConnectivityManager;.registerDefaultNetworkCallback (Landroid/net/ConnectivityManager$NetworkCallback;)V
01-29 21:07:01.365 W/dalvikvm(29185): Unable to resolve superclass of Landroidx/work/impl/constraints/trackers/NetworkStateTracker$NetworkStateCallback; (341)
01-29 21:07:01.365 W/dalvikvm(29185): Link of class 'Landroidx/work/impl/constraints/trackers/NetworkStateTracker$NetworkStateCallback;' failed
01-29 21:07:01.365 I/dalvikvm(29185): Could not find method android.net.ConnectivityManager.unregisterNetworkCallback, referenced from method androidx.work.impl.constraints.trackers.NetworkStateTracker.stopTracking
01-29 21:07:01.365 W/dalvikvm(29185): VFY: unable to resolve virtual method 1872: Landroid/net/ConnectivityManager;.unregisterNetworkCallback (Landroid/net/ConnectivityManager$NetworkCallback;)V
01-29 21:07:01.365 D/dalvikvm(29185): VFY: replacing opcode 0x6e at 0x0018
01-29 21:07:01.370 W/dalvikvm(29185): Unable to resolve superclass of Landroidx/work/impl/constraints/trackers/NetworkStateTracker$NetworkStateCallback; (341)
01-29 21:07:01.370 W/dalvikvm(29185): Link of class 'Landroidx/work/impl/constraints/trackers/NetworkStateTracker$NetworkStateCallback;' failed
01-29 21:07:01.370 D/dalvikvm(29185): DexOpt: unable to opt direct call 0x593e at 0x17 in Landroidx/work/impl/constraints/trackers/NetworkStateTracker;.<init>

And at the time the logs are taken by the user, the app dumps the current work queue, and sure enough there is a periodic work still enqueued (but this periodic work doesn't run when network has been restored and never seems to run again)... this is the log entry here:

01-29 21:11:33.875 D/Meteogram_ConfigActvty(29556): ********** LOG OF WORK QUEUE **********
01-29 21:11:34.175 D/Meteogram_Worker(29556): workInfo: WorkInfo{mId='8eaea234-7001-479e-ae88-2d628f57a62b', mState=ENQUEUED, mOutputData=androidx.work.Data@0, mTags=[widget-43443, com.cloud3squared.meteogram.MeteogramWorker, periodic]}
01-29 21:11:34.175 D/Meteogram_Worker(29556): workInfo: WorkInfo{mId='c43771c7-6b71-49fb-a2ee-c8486b37b798', mState=SUCCEEDED, mOutputData=androidx.work.Data@0, mTags=[widget-43443, com.cloud3squared.meteogram.MeteogramWorker, onetime]}
01-29 21:11:34.175 D/Meteogram_ConfigActvty(29556): ********** END OF WORK QUEUE **********

The above is logged by the following function, with the widget id passed in to get the tag (same method as in previous post), and filtering the work on this tag:

    static void logWorkQueue(int appWidgetId) {
        String tag = getWorkTag(appWidgetId);
        WorkManager workManager = WorkManager.getInstance();
        ListenableFuture<List<WorkInfo>> workInfos = workManager.getWorkInfosByTag(tag);
        try {
            List<WorkInfo> workInfoList = workInfos.get();
            for (WorkInfo workInfo : workInfoList) {
                Log.d(TAG, "workInfo: " + workInfo.toString());
            }
        } catch (ExecutionException e) {
            e.printStackTrace();
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }

Further update: it's just possible that this isn't specifically related to the network constraint.  This user has now reported that a even a non-network-constrained periodic work seems to have stopped (as manifested by the associated widget no longer auto updating).  I don't have logs for this, but maybe some of those log entries around 21:07 from the previous logcat might also be occurring even for periodic work that is not network constrained?  Until now, the non-network-constrained periodic work does however seem to be more reliable... network constrained periodic work seems consistently to stop after a period without network.

Thanks for the details. I should have updated the thread yesterday. I think I know what might be going on.
I have a pending CL as well. It should be fixed in the next beta.

https://android-review.googlesource.com/c/platform/frameworks/support/+/889839

This is excellent news... thanks for checking it out so carefully, and fingers crossed... look forward to the next beta and will report back either way.  

Any ETA on the next beta?

Keep up the good work on this really useful library!

Project: platform/frameworks/support
Branch: androidx-master-dev

commit 177837514245d5bb24cc8e9bc27f20503e23e308
Author: Rahul Ravikumar <rahulrav@google.com>
Date:   Tue Jan 29 17:50:14 2019

    Fixes ConstraintsCommandHandler that correctly enables and disables proxies.
   
    * ConstraintsCommandHandler was only looking at work that was eligible to be scheduled.
      This is incorrect, as we may have Workers that are scheduled, but are pending execution due
      to an unmet constraint. We need to look at all scheduled work which is unfinished.
    * The only reason why this worked before with integration tests was due to one of 2 reasons:
      * The process was in the foreground anyway, and there was an active WorkConstraintTracker.
      * Enabling / disabling airplane mode (to test Network Constraints) would have caused a
        TIME_SET broadcast in some cases where we reschedule everything (RescheduleReceiver).
   
    Test: Updated SystemAlarmDispatcherTests & integration tests on API 22 with the Battery charging
          Constraint that has no other side effects.
   
    Change-Id: Ib973931b47be915dd8f533e1e651b6c1a29843f9
    Fixes: b/123379508

M       work/workmanager/src/androidTest/java/androidx/work/impl/background/systemalarm/SystemAlarmDispatcherTest.java
M       work/workmanager/src/main/java/androidx/work/impl/background/systemalarm/ConstraintsCommandHandler.java
M       work/workmanager/src/main/java/androidx/work/impl/background/systemalarm/RescheduleReceiver.java
M       work/workmanager/src/main/java/androidx/work/impl/model/WorkSpecDao.java

https://android-review.googlesource.com/889839
https://goto.google.com/android-sha1/177837514245d5bb24cc8e9bc27f20503e23e308

Any ETA for beta04?  Am desperate to try it out..

Looking at early next week.

OK, thanks!

I'm still seeing this problem, or seeing it again.  I'm monitoring (at a server) requests from the device of the same user (Android 4.3), and can see that a periodic work request seems to run OK for a time, but when the device is idle and without network, when the device is given network again, not only does the late work not run, but no work ever seems to run again.  And a log output of all work does still show that a periodic work is enqueued, but it just never seems to run again.

Are the tests you ran when fixing this before still working?  Or has something subsequently messed it up?  Or maybe I'm seeing another issue altogether.

Please give us a sample project.  I think that's the simplest way for us to take a look at exactly what's happening for you.  Which device are you running this on?

Device is as per #16 -- Samsung Galaxy S3 running Android 4.3

Can you reproduce the same behavior using a stock Android device/emulator?

Not as yet; am trying now.

Is there any way of querying a bit more information about enqueued work requests?  The most information I can get at the moment is something like:

02-15 17:37:31.535 D/My_Worker(11599): workInfo: WorkInfo{mId='00db2ea7-07d6-42a1-a506-a26ff8e3217d', mState=ENQUEUED, mOutputData=androidx.work.Data@0, mTags=[com.example.myapp.MyWorker, widget-43806, periodic]}
02-15 17:37:31.535 D/My_Worker(11599): workInfo: WorkInfo{mId='08bce448-5d4a-4a17-89d2-6fdce6ef1091', mState=SUCCEEDED, mOutputData=androidx.work.Data@0, mTags=[com.example.myapp.MyWorker, widget-43806, backstop]}

And the only reason I can even tell if the work item is periodic or not is because I tag it with 'periodic' if it is.  Otherwise, all I get is a work ID and a state... would be really handy to know when it last ran, when it is due to run next, etc.  Would be very useful not least for debugging purposes.

As suggested: https://issuetracker.google.com/issues/123222823

You need to enable verbose logs. That will tell us a lot more.

Also, if you are going into a SUCCEEDED state, that mean your Worker is actually not periodic. PeriodicWork never goes into a terminal state unless it has been cancelled.
It always goes back to ENQUEUED for the next interval.

As per #9 above.  Yes, the 4.3 user is currently running a test version with this verbose logging enabled to see if I can get something interesting from it.

For reference all WorkManager logs are prefixed with a "WM-".

#39: indeed, but the SUCCEEDED entry is a onetime worker... it is not tagged with 'periodic' but only 'backstop' (which is a onetime request).

I've seen this behaviour now on the 4.3 emulator.  I started a periodic work request (for updating a widget) with network constraint and interval of one hour (flex of 30 mins).  I put the emulator into airplane mode and came back some time later.  On disabling airplane mode the widget did update immediately but the trigger was ON_ENABLED for the widget and not the late work request.  Thereafter, I left the widget for an hour, and nothing happened... the periodic work that was meant to trigger an update hasn't happened.  I meant to dump the alarm state with "adb shell dumpsys alarm" but unfortunately I reset the widget before doing so.  Will next time.  Sorry it's a bit nebulous thus far... I will try to bring more concrete information next time but there's definitely still something not right with network-constrained periodic work on Android 4.3.

Yes, please send us a sample project when you have it.

I'll try, but am short of time over next few days.  Tempting just to set minsdk to 21 and be done with it!

I have some logs to post... would that be of assistance in lieu of a sample project for now?

Yes, please send them

Logs attached, from the user's Android 4.3 device.  During the period in which the logs were generated, the periodic work concerned should have fired (to cause a widget to update) at least twice but failed to do so.  The periodic work was on a 30 minute interval, with 15 minute flex interval.  With network constraint.  After enqueuing the periodic work, the device was without network for a time, then network was restored.  But periodic work failed to trigger.  I schedule the periodic work basically as described in #22 *except* that I now use a flex interval (to address a double running of work as per another issue).

There seems to be lots of "D/WM-" stuff in there that refers to constraints... hopefully something of interest.

Some further information which may be of interest...

To see if it made a difference, I went back to NOT using a flexInterval, i.e. using:

    workRequestBuilder = new PeriodicWorkRequest.Builder(MeteogramWorker.class, interval, TimeUnit.MILLISECONDS);

INSTEAD of:

    workRequestBuilder = new PeriodicWorkRequest.Builder(MeteogramWorker.class, interval, TimeUnit.MILLISECONDS, flexInterval, TimeUnit.MILLISECONDS);

And without using flexInterval, behaviour seems to be FAR more reliable so far.  The periodic work (with network constraint) has so far survived some degree of testing (on the user device): letting the periodic work fire a few times, then turning off network for one or more scheduled firings, then network back on... and each time so far the "missed" work runs straight away.

It's far from an extensive test yet, but it seems like it can't be coincidence... the above change (to NOT use flexInterval) is all I've changed, and it is performing better so far.

After *this current* issue (i.e. #123379508) was marked fixed on 30 Jan, a change was made to WorkManager flexInterval behaviour on 13 Feb as per the following:

https://issuetracker.google.com/issues/124274584

Would it have anything to do with that?  Between #123379508 being fixed (30 Jan) and #124274584 being fixed (13 Feb), I think that things were going well.  It seemed to be after #124274584 was fixed that things went downhill again.  Again, I can't be certain, but it's a lead anyway.

P.S. the only reason I started using flexInterval in the first place was to address the issue reported here:

https://issuetracker.google.com/issues/123804615#comment8

BTW the logs in #48 were BEFORE I made the change mentioned in #49, i.e. using flexInterval

I looked at the logs. It looks like the ConstraintTracker correctly tries to start the work, but the device subsequently reports that the constraints are unmet when trying to run the Worker.

02-17 14:02:25.255 D/WM-ConstraintTracker( 1608): NetworkStateTracker: initial state = [ Connected=false Validated=false Metered=false NotRoaming=false ]. This happens twice, like you described.

This is expected behavior. I think your disabling of flex has nothing to do with why the Worker was running when you had flex. I think the device does not have access to a reliable network as far as I can tell.

It's a WiFi network... not saying that is necessary "reliable" but it surely is unlikely to be consistently unreliable?

And how do you explain why NOT specifying a flexInterval results in completely reliable periodic behaviour?  While specifying a flexInterval makes it fall apart?  

I don't follow your comment about expected behaviour... in the period of the logs, the device had no WiFi for at least two expected periodic runs, but didn't run because there was no network.  That's expected behaviour, yes.  What is not expected is that even when network was restored, the work did not run, ever again.  That is when specifying a flexInterval.

But when not specifying a flexInterval, it all works smoothly... that doesn't make sense does it?

Am getting reports in now from said user... it's running like clockwork with the version that doesn't specify flexInterval when setting up the periodic work request.

Specifying flex does nothing except delay the Worker in the AlarmManager implementation.
There is absolutely no difference in how constraints are handled.

Also, from the logs that you attached, it is clear that the device was not connected to a network. That's what I am basing this on. (NetworkStateTracker: initial state = [ Connected=false Validated=false Metered=false NotRoaming=false ]).

If you still think there might be something else going on, I think the best thing to do is to send us a sample app to reproduce this on our end.

There are two such logs entries (one of which you quote above) that say "Connected=false".

But there is a third one, later, that says "Connected=true":

02-17 14:40:50.345 D/WM-ConstraintTracker( 3798): NetworkStateTracker: initial state = [ Connected=true Validated=false Metered=false NotRoaming=true ]

And then immediately after:

02-17 14:40:50.345 D/WM-WorkConstraintsTrack( 3798): Constraints met for 635bfec6-81c9-499a-a9d2-5e273f07573c

So why did the work not run?

So I think we're going very very deep into a bug that we cannot reproduce.  Please send us a sample project.

Trouble is, I think this may be quite specific to that device.  I can't reproduce it on the emulator (what I thought I was seeing in #43 was actually something else).  So all we have to go on is the logs from the user device.  I thought the D/WM- log entries would help... clearly not.  Is it not possible to determine from those why the work constraints were met at 02-17 14:40:50.345 and yet the work did not execute?

Here is another instance, today, where the network-constrained periodic work (widget update) failed to run on the user's Android 4.3 device after turning the WiFi back on first thing this morning... see attached logs, with relevant entries below:

02-20 10:28:12.735 D/WM-ConstraintProxy( 1227): onReceive : Intent { act=android.net.conn.CONNECTIVITY_CHANGE flg=0x8000010 cmp=com.cloud3squared.meteogram.devpro/androidx.work.impl.background.systemalarm.ConstraintProxy$NetworkStateProxy (has extras) }

02-20 10:28:14.770 D/WM-ConstraintTracker( 1227): NetworkStateTracker: initial state = [ Connected=true Validated=false Metered=false NotRoaming=true ]

02-20 10:28:14.815 D/WM-WorkConstraintsTrack( 1227): Constraints met for 5d210711-4c14-43cb-b6ea-2a6de910d76a

And yet, after this, the work doesn't run... there are no log entries from the startWork() function of the associated Worker.