Screen filter service being started multiple times

[smichel17]

Somehow, the service that shows the screen filter gets started multiple times, causing all kinds of weird behavior. This bug has been around for a while, but seems to happen randomly; I've never been able to reproduce it. I suspect it causes #139, which would explain why that bug is hard to reproduce.

It's an especially tricky bug because it's hard (impossible?) to spot from logs alone. edit 9/1/2017: it definitely is possible to spot from logs, but I was never able to get logs to know that. On the upside, there is a relatively easy way to know for sure whether you are experiencing it: look at your phone's running services, and see if Red Moon lists two.

In order to do this, you need to put your phone in developer mode. All this does is enable another category in the settings with additional options. The quote below describes how to do it. It's a one-time thing, so if you've done it before, you don't need to do it again.

1. Open your phone's Settings.
2. In Settings, find and open About phone.
3. In About phone, find Build Number and tap on it 7 times.

A message should pop up that says "you are now a developer".

Once you've enabled developer mode:

1. Open your phone's Settings again
2. In Settings, find and open Developer options. It's usually right above About phone.
3. In Developer options, scroll down and open Running services. I believe it's usually near the top. On my phone, it's the 5th one down.
4. In Running services, scroll down and open Red Moon (or Red Moon Debug, if you're using a debug version).
5. In Red Moon, check to see if ScreenFilterService appears more than once.
6. Do the same thing, but this time check Cached processes instead of Running services.
   • Repeat steps 1-3
   • In Running services, find and open Cached processes. Sometimes this is a super obvious tab; sometimes it's in a menu.
   • In Cached processes, repeat steps 4-5.

If ScreenFilterService appears more than once in either of those locations, or if it appears in both locations, then we're talking about this bug.

---

I'm pretty sure the only way you can start two of the same service is if they're in different processes. I don't know how we're managing to start two different Red Moon processes. My best guess is that it's related to starting Red Moon from different places (timer/switch/widget/tile). If you're familiar with these technical details and can guess at how we're starting multiple services, that would be super helpful.

[smichel17]

@raatmarien @leoauri @stefanbrand @rplevka @joeyjbeckman

[StefanBrand]

I'm on Kitkat 4.4.2 (Fairphone 1 / MT6589 chipset) and can find the requested information in Settings > Apps > Active. In the same view there is a button in the upper right corner, leading to cached processes.

However, Red Moon is only listed in Active Apps and it has only 1 process and 1 service. #97 persists though.

[leoauri]

I'm on 4.2.2, also Fairphone 1, it's in "manage apps > running". I also only see one service running (active, not cached), I'll check again when I see some of that weird behaviour.

[smichel17]

I'll check again when I see some of that weird behaviour.

Yeah, it doesn't happen most of the time; you wouldn't see it unless you're experiencing weird behavior.

The closest I've ever come to reproducing it reliable was somewhere in development between v2.10.2 and v3.0.0, I could get it sometimes in an android 7.0 emulator by rapidly turning on and off via the quick settings tile and every so often opening/closing the ui and then swiping it aside in 'Recent apps'. But I never figured out what pattern actually did it.

My best guess is that it's related to whether Android keeps stuff around in memory, which would explain why it's unreliable, since other apps running on your phone can influence it.

[leoauri]

I just got some weird behaviour (filter wasn't reactivated after leaving secure app), but no sign of multiple services that I could see

[smichel17]

I believe I've finally fixed this. Here's a post-mortem:

---

I was (finally!) able to reproduce this with the following steps. Pretty sure I was building from a63bbf04.

1. Enable app monitoring ("Pause in secure apps"), enable the timer, and disable "Times from sun"
2. Make sure Red Moon has not been granted the location permission
3. Start the filter
4. Go to the 'timer' screen, and enable "Times from sun"
   • Decline or accept the permissions request. Declining makes step 2 less work if you're going to do this again.
   • Notice that the filter resumes
5. Go back to the main screen.
   • The slider at the top should be OFF
6. Enable the slider
   • A second filter is started

So, what happened? Well, in that commit, each time we receive a command, we'd check to see if we had permission to show the overlay (source). It turns out, if you do this check while a permissions dialog (or other secure app) is being shown, it reports that we do not have permission, even though the user has granted it.

• Since the service thinks it doesn't have permission, it kills itself, but it does so without explicitly hiding the overlay.
• Apparently the android system decides to hide the overlay anyway instead of leaving the permission dialog unresponsive.
• When the dialog is closed, the system does us another favor and restores the overlay.
  • In order to do this, the system must be storing a reference to the overlay (view) itself, preventing it from being garbage collected.
• The main activity correctly detects that the service is not running, and sets the switch position off.
• Turning the switch on starts a new service, which puts a new overlay on the screen, even though the old one is still displayed.

So, why was this so hard to reproduce?

When you leave or stop an app, it becomes vulnerable to garbage collection. But, Android often delays garbage collection for quite a bit, holding the process in the cache in case you return to the app. In this case, step 6 delivers the command to the existing service, which knows that the overlay is already shown and skips doing so again. Most of the time you're just pausing red moon for a second or two during the permissions dialog, so the service was rarely garbage collected.

I'm not sure why the bug became reliable. Maybe Service.stopSelf() always triggers immediate garbage collection on the service?

In any case, now we make sure to hide the overlay, restore the brightness, etc if the service is stopped for any reason, so I think we can finally lay this one to rest.