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

PinWatchers are not started sometimes, when the app is in background #764

Closed
K1rakishou opened this issue Feb 28, 2020 · 6 comments
Closed

PinWatchers are not started sometimes, when the app is in background #764

K1rakishou opened this issue Feb 28, 2020 · 6 comments
Labels
bug Something isn't working

Comments

@K1rakishou
Copy link

K1rakishou commented Feb 28, 2020 •
edited
Loading

Or rather, PinWatchers are getting created but they are not getting updated, i.e. they do not load new posts. Usually this happen on first app wake up after it getting killed. Here is the first app wake up:

2020-02-28 15:19:47.312 D/Kuroba-dev | WakeUpdateReceiver: Alarm trigger at 3:19:47 PM
2020-02-28 15:19:47.315 I/Kuroba-dev | FilterWatchManager: Processing filter loaders, started at 3:19:47 PM
2020-02-28 15:19:47.320 D/Kuroba-dev | FilterWatchManager: Number of filter loaders: 0
2020-02-28 15:19:47.322 D/Kuroba-dev | WatchManager: updateState watchEnabled=true backgroundEnabled=true foreground=false
2020-02-28 15:19:47.323 D/Kuroba-dev | WatchManager: No pins found with download flag
2020-02-28 15:19:47.324 D/Kuroba-dev | WatchManager: Setting interval type from NONE to BACKGROUND
2020-02-28 15:19:47.324 D/Kuroba-dev | WakeManager: Registered class com.github.adamantcheese.chan.core.manager.WatchManager
2020-02-28 15:19:47.327 D/Kuroba-dev | PinWatcher: created for Loadable{id=806, mode=0, board='g', no=74923XXX', listViewIndex=42, listViewTop=-382, lastViewed=74924XXX, lastLoaded=74924XXX, markedNo=-1, dirty=false, loadableDownloadingState=NotDownloading}
2020-02-28 15:19:47.331 D/Kuroba-dev | Dependency Injection: Saved thread loader manager
2020-02-28 15:19:47.333 D/Kuroba-dev | PinWatcher: created for Loadable{id=794, mode=0, board='g', no=74922XXX', listViewIndex=9, listViewTop=-325, lastViewed=74924XXX, lastLoaded=74924XXX, markedNo=-1, dirty=false, loadableDownloadingState=NotDownloading}
2020-02-28 15:19:47.333 D/Kuroba-dev | PinWatcher: created for Loadable{id=828, mode=0, board='g', no=74924XXX', listViewIndex=11, listViewTop=-423, lastViewed=74924XXX, lastLoaded=74924XXX, markedNo=-1, dirty=false, loadableDownloadingState=NotDownloading}
2020-02-28 15:19:47.333 D/Kuroba-dev | PinWatcher: created for Loadable{id=812, mode=0, board='g', no=74923XXX', listViewIndex=31, listViewTop=-473, lastViewed=74924XXX, lastLoaded=74924XXX, markedNo=-1, dirty=false, loadableDownloadingState=NotDownloading}
2020-02-28 15:19:47.825 D/Kuroba-dev | BoardRepository: updateAvailableBoardsForSite changed = false
2020-02-28 15:19:47.963 D/Kuroba-dev | BoardRepository: updateAvailableBoardsForSite changed = false
2020-02-28 15:19:49.363 D/Kuroba-dev | WakeUpdateReceiver: Alarm trigger at 3:19:49 PM
2020-02-28 15:19:49.364 W/Kuroba-dev | WakeManager: Background update broadcast ignored because it was requested too soon

And here is the second one:

2020-02-28 15:22:25.387 D/Kuroba-dev | WakeUpdateReceiver: Alarm trigger at 3:22:25 PM
2020-02-28 15:22:25.387 D/Kuroba-dev | WatchManager: update() from background
2020-02-28 15:22:25.387 D/Kuroba-dev | PageRequestManager: Requesting new board pages
2020-02-28 15:22:25.420 D/EventBus: No subscribers registered for event class com.github.adamantcheese.chan.core.manager.WatchManager$PinMessages$PinChangedMessage
2020-02-28 15:22:25.420 D/Kuroba-dev | ChanThreadLoader: Requested /g/, 74923XXX
2020-02-28 15:22:25.421 D/EventBus: No subscribers registered for event class org.greenrobot.eventbus.NoSubscriberEvent
2020-02-28 15:22:25.421 D/Kuroba-dev | PageRequestManager: Requesting new board pages
2020-02-28 15:22:25.422 D/EventBus: No subscribers registered for event class com.github.adamantcheese.chan.core.manager.WatchManager$PinMessages$PinChangedMessage
2020-02-28 15:22:25.422 D/EventBus: No subscribers registered for event class org.greenrobot.eventbus.NoSubscriberEvent
2020-02-28 15:22:25.422 D/Kuroba-dev | PageRequestManager: Requesting new board pages
2020-02-28 15:22:25.424 D/EventBus: No subscribers registered for event class com.github.adamantcheese.chan.core.manager.WatchManager$PinMessages$PinChangedMessage
2020-02-28 15:22:25.424 D/EventBus: No subscribers registered for event class org.greenrobot.eventbus.NoSubscriberEvent
2020-02-28 15:22:25.424 D/Kuroba-dev | PageRequestManager: Requesting new board pages
2020-02-28 15:22:25.425 D/EventBus: No subscribers registered for event class com.github.adamantcheese.chan.core.manager.WatchManager$PinMessages$PinChangedMessage
2020-02-28 15:22:25.425 D/EventBus: No subscribers registered for event class org.greenrobot.eventbus.NoSubscriberEvent
2020-02-28 15:22:25.427 I/Kuroba-dev | WatchManager: 4 pin watchers beginning updates, started at 3:22:25 PM
2020-02-28 15:22:25.429 D/Kuroba-dev | ChanThreadLoader: Requested /g/, 74922XXX
2020-02-28 15:22:25.430 D/Kuroba-dev | ChanThreadLoader: Requested /g/, 74924XXX
2020-02-28 15:22:25.431 D/Kuroba-dev | ChanThreadLoader: Requested /g/, 74923XXX
2020-02-28 15:22:25.441 D/Kuroba-dev | ChanReaderRequest: Thread count: 8
2020-02-28 15:22:25.743 D/Kuroba-dev | PageRequestManager: Got pages for 4chan /g/
2020-02-28 15:22:26.222 D/Kuroba-dev | Dependency Injection: Theme helper
2020-02-28 15:22:26.515 D/Kuroba-dev | PinWatcher: postlast=19 postnew=19 werenewposts=false quotelast=2 quotenew=2 werenewquotes=false nextload=9s
2020-02-28 15:22:26.516 D/EventBus: No subscribers registered for event class com.github.adamantcheese.chan.core.manager.WatchManager$PinMessages$PinChangedMessage
2020-02-28 15:22:26.516 D/EventBus: No subscribers registered for event class org.greenrobot.eventbus.NoSubscriberEvent
2020-02-28 15:22:26.706 D/Kuroba-dev | PinWatcher: postlast=47 postnew=49 werenewposts=true quotelast=0 quotenew=0 werenewquotes=false nextload=9s
2020-02-28 15:22:26.707 D/EventBus: No subscribers registered for event class com.github.adamantcheese.chan.core.manager.WatchManager$PinMessages$PinChangedMessage
2020-02-28 15:22:26.707 D/EventBus: No subscribers registered for event class org.greenrobot.eventbus.NoSubscriberEvent
2020-02-28 15:22:26.715 D/Kuroba-dev | PinWatcher: postlast=39 postnew=40 werenewposts=true quotelast=0 quotenew=0 werenewquotes=false nextload=9s
2020-02-28 15:22:26.715 D/EventBus: No subscribers registered for event class com.github.adamantcheese.chan.core.manager.WatchManager$PinMessages$PinChangedMessage
2020-02-28 15:22:26.715 D/EventBus: No subscribers registered for event class org.greenrobot.eventbus.NoSubscriberEvent
2020-02-28 15:22:26.717 D/Kuroba-dev | PinWatcher: postlast=16 postnew=16 werenewposts=false quotelast=0 quotenew=0 werenewquotes=false nextload=9s
2020-02-28 15:22:26.718 D/EventBus: No subscribers registered for event class com.github.adamantcheese.chan.core.manager.WatchManager$PinMessages$PinChangedMessage
2020-02-28 15:22:26.718 D/EventBus: No subscribers registered for event class org.greenrobot.eventbus.NoSubscriberEvent
2020-02-28 15:22:26.719 I/Kuroba-dev | WatchManager: All watchers updated, finished at 3:22:26 PM
2020-02-28 15:22:27.759 D/Kuroba-dev | WatchManager: updateState watchEnabled=true backgroundEnabled=true foreground=false

Third one is the same as the second one:

2020-02-28 15:25:05.398 D/Kuroba-dev | WakeUpdateReceiver: Alarm trigger at 3:25:05 PM
2020-02-28 15:25:05.398 D/Kuroba-dev | WatchManager: update() from background
2020-02-28 15:25:05.409 D/EventBus: No subscribers registered for event class com.github.adamantcheese.chan.core.manager.WatchManager$PinMessages$PinChangedMessage
2020-02-28 15:25:05.409 D/EventBus: No subscribers registered for event class org.greenrobot.eventbus.NoSubscriberEvent
2020-02-28 15:25:05.410 D/Kuroba-dev | ChanThreadLoader: Requested /g/, 74923XXX
2020-02-28 15:25:05.420 D/EventBus: No subscribers registered for event class com.github.adamantcheese.chan.core.manager.WatchManager$PinMessages$PinChangedMessage
2020-02-28 15:25:05.420 D/EventBus: No subscribers registered for event class org.greenrobot.eventbus.NoSubscriberEvent
2020-02-28 15:25:05.421 D/Kuroba-dev | ChanThreadLoader: Requested /g/, 74922XXX
2020-02-28 15:25:05.426 D/EventBus: No subscribers registered for event class com.github.adamantcheese.chan.core.manager.WatchManager$PinMessages$PinChangedMessage
2020-02-28 15:25:05.426 D/EventBus: No subscribers registered for event class org.greenrobot.eventbus.NoSubscriberEvent
2020-02-28 15:25:05.426 D/Kuroba-dev | ChanThreadLoader: Requested /g/, 74924XXX
2020-02-28 15:25:05.429 D/EventBus: No subscribers registered for event class com.github.adamantcheese.chan.core.manager.WatchManager$PinMessages$PinChangedMessage
2020-02-28 15:25:05.429 D/EventBus: No subscribers registered for event class org.greenrobot.eventbus.NoSubscriberEvent
2020-02-28 15:25:05.430 D/Kuroba-dev | ChanThreadLoader: Requested /g/, 74923XXX
2020-02-28 15:25:05.431 I/Kuroba-dev | WatchManager: 4 pin watchers beginning updates, started at 3:25:05 PM
2020-02-28 15:25:05.811 D/Kuroba-dev | PinWatcher: postlast=47 postnew=49 werenewposts=false quotelast=0 quotenew=0 werenewquotes=false nextload=14s
2020-02-28 15:25:05.812 D/EventBus: No subscribers registered for event class com.github.adamantcheese.chan.core.manager.WatchManager$PinMessages$PinChangedMessage
2020-02-28 15:25:05.812 D/EventBus: No subscribers registered for event class org.greenrobot.eventbus.NoSubscriberEvent
2020-02-28 15:25:05.825 D/Kuroba-dev | PinWatcher: postlast=39 postnew=40 werenewposts=false quotelast=0 quotenew=0 werenewquotes=false nextload=14s
2020-02-28 15:25:05.826 D/EventBus: No subscribers registered for event class com.github.adamantcheese.chan.core.manager.WatchManager$PinMessages$PinChangedMessage
2020-02-28 15:25:05.826 D/EventBus: No subscribers registered for event class org.greenrobot.eventbus.NoSubscriberEvent
2020-02-28 15:25:06.320 D/Kuroba-dev | PinWatcher: postlast=16 postnew=16 werenewposts=false quotelast=0 quotenew=0 werenewquotes=false nextload=14s
2020-02-28 15:25:06.320 D/EventBus: No subscribers registered for event class com.github.adamantcheese.chan.core.manager.WatchManager$PinMessages$PinChangedMessage
2020-02-28 15:25:06.320 D/EventBus: No subscribers registered for event class org.greenrobot.eventbus.NoSubscriberEvent
2020-02-28 15:25:06.335 D/Kuroba-dev | PinWatcher: postlast=19 postnew=19 werenewposts=false quotelast=2 quotenew=2 werenewquotes=false nextload=14s
2020-02-28 15:25:06.336 D/EventBus: No subscribers registered for event class com.github.adamantcheese.chan.core.manager.WatchManager$PinMessages$PinChangedMessage
2020-02-28 15:25:06.336 D/EventBus: No subscribers registered for event class org.greenrobot.eventbus.NoSubscriberEvent
2020-02-28 15:25:06.338 I/Kuroba-dev | WatchManager: All watchers updated, finished at 3:25:06 PM
2020-02-28 15:25:07.337 D/Kuroba-dev | WatchManager: updateState watchEnabled=true backgroundEnabled=true foreground=false

Notice that there are ChanThreadLoader calls now:

2020-02-28 15:22:25.429 D/Kuroba-dev | ChanThreadLoader: Requested /g/, 74922XXX
2020-02-28 15:22:25.430 D/Kuroba-dev | ChanThreadLoader: Requested /g/, 74924XXX
2020-02-28 15:22:25.431 D/Kuroba-dev | ChanThreadLoader: Requested /g/, 74923XXX
@K1rakishou K1rakishou added the bug Something isn't working label Feb 28, 2020
@K1rakishou
Copy link
Author

K1rakishou commented Feb 28, 2020 •
edited
Loading

Maybe I fucked up something when touching ChatThreadLoader yesterday. But I think I first noticed this thing even before that.

@K1rakishou
Copy link
Author

K1rakishou commented Feb 28, 2020 •
edited
Loading

Alright, this only happens once, the very first update call after the app has been killed, and happens because we now force call onBroadcastReceived() every time the app goes to foreground. And for some unknown reason this messes up the lastBackgroundUpdateTime so if you kill the app, then on the next update lastBackgroundUpdateTime will have the current time instead of 0. I have no idea why is this happening. I honestly don't know what to do here. I could extract the wakeable iteration loop into a separate method and call it instead when the app goes to foreground but I dunno.

@Adamantcheese Adamantcheese changed the title [REGRESSION] PinWatchers are not started sometimes, when the app is in background PinWatchers are not started sometimes, when the app is in background Mar 5, 2020
@Adamantcheese
Copy link
Owner

This isn't a regression, just Android being Android. It's a pretty old issue considering I found this: https://github.com/evernote/android-job/issues/128, but someone recently submitted a bug report https://issuetracker.google.com/issues/149556385.

@K1rakishou
Copy link
Author

I mean you can clearly see that it doesn't notify Wakeables because lastBackgroundUpdateTime is the current time instead of zero (because the app was killed so it should contain the default value) for some reason. So that's another problem.

@Adamantcheese
Copy link
Owner

Figured it out. If you've got a foreground service running (ie the watch notification), then all resources will be kept in-memory, so a swiped-away app is technically still running. That means that all the PinWatchers are still in memory (therefore don't need to be created), the lastBackgroundUpdateTime variable retains what it was when it was previously before the activity was destroyed, and the alarms still keep running to run any wakeables. PinWatchers are still updated just fine in this state from my testing, there's just that annoying bit for "No subscribers" being spammed in the logs, which I'll leave this issue open for.

tl:dr; no bugs to me, all good

@K1rakishou
Copy link
Author

Figured it out. If you've got a foreground service running (ie the watch notification), then all resources will be kept in-memory, so a swiped-away app is technically still running.

Oh yeah, this explains it.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@Adamantcheese @K1rakishou