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.

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

Bug at AlarmScheduler#fireAlarmsInThePast #533

Closed
Skylarkarms opened this issue Mar 7, 2023 · 8 comments
Closed

Bug at AlarmScheduler#fireAlarmsInThePast #533

Skylarkarms opened this issue Mar 7, 2023 · 8 comments
Labels

Comments

@Skylarkarms
Copy link

Skylarkarms commented Mar 7, 2023

Description:

If a sequence of alarms is set AND as long as the FIRST and LAST alarms in the sequence have the exact same time... ALL ALARMS will be fired at once; once the time for one of BOTH (with the same time) to be fired finally arrives.

To Reproduce:

  • Given:
    Set 3 alarms:

    • 2 alarms at now() + 1 minute (for testing sake)

      Both alarms must have the exact same time.

    • 1 alarm at whatever time set in the future (greater than the 2 alarms you just set).
    • Deactivate all 3 alarms.
    • Close app.
  • When:

    • Open app.
    • Activate ONE of the 2 alarms with repeating time (now() + 1min)
    • Activate the one that has a diff time.
    • As third alarm you'll activate the second alarm with repeated time.
  • Then
    *Wait till the time comes...

Expected and observed behavior

fireAlarmsInThePast() Will check the first item at the queue:

queue.peek()

It will ask if it is before now:

.before(now)

It will return true since 2 of the alarms are set to the exact same time.... one of them is placed at the head of the queue.
By the time the second call arrives... the epochMillis will be set AFTER the call which will answer TRUE to the question: "Is this call supposed to be set in the past?", TRUE... because calls are not solved concurrently so the sequence of the second call may be late by a couple millis (This is my speculation of the why this method even exist...).

Finally, it will poll EVERYTHING and setter.fireNow() will set the alarm in the middle of the queue by accident.

   queue.poll()?.let { firedInThePastAlarm ->
        setter.fireNow(firedInThePastAlarm.id, firedInThePastAlarm.type.name)
      }

I have no solution since I am yet to fully understand the architecture, one of the things I don't understand is why this queue is not being re-populated by alarms that where set before re-installing the app and opening it again.

Maybe this is a second possible bug. Maybe not since I am re-installing the app, but this is most likely a bug since the DB is not getting cleared, so it should be repopulated by the previous enabled alarms(?).

@Skylarkarms Skylarkarms added the bug label Mar 7, 2023
@Skylarkarms
Copy link
Author

To elaborate a little bit more on the reasons why this bug may have risen...
It seems that the way PendingIntents are handled In Android 12 - 13, the way in which Intents get managed in the Manager differs from other versions in the way in which they handle their persistence upon closing of the App.
This means that in this version, the usual way of scheduling intents will not provide the persistence once the App is closed (I think...).

This is my guess... as to the reason WHY they chose to manage the Intent queue manually....
Because of this, the system is not forced to use a unique requestCode for each Intent.... and so they are using the same requestCode for each PendingIntent delivered...
Because of this (using the same request code), ALL intents get overridden by the next Intent delivered.

And so, the cache, called 'queue' in 'AlarmsScheduler.class' was created.

Each time an alarm gets fired, this queue via the method replaceAlram() schedules the next Intent.
The method gets trigger via a feedback loop in which the onReceive() RE-triggers a transition towards "Enable" a second time... I believe there have been some fixes along this transition in order to distinguish a real "Enable"(UI toogle) from a system (RE)enabling, then it ends up accessing some cache (not even the queue but maybe the Store or the AlarmStore) and somewhere I cannot find where, allows the enabling of the next alarm of different id.

The clear way would be to use a unique requestCode for each PendingIntent and erase this cache.
The next step is finding and fixing the reason why we required this cache in the first place.

BTW this project is how I learned about StateMachines and it is awesome design.

I'll see if I can find an easy solution.

@yuriykulikov
Copy link
Owner

Hello @Skylarkarms ,

thank you for writing the issue and for your PR. I am trying to understand the problem. Could you perhaps capture some logs for me?
As for the fix, I was kind of assuming that it will be isolated in AlarmsScheduler...

@Skylarkarms
Copy link
Author

Skylarkarms commented Mar 10, 2023

The way to capture the bug properly would be to, via reflection, read the PendingIntent queue inside AlarmManager, otherwise the only way is to trust in its only method manager.nextAlarmClock which allows us to read the immediate next Intent in the queue.

Logs were giving null upon the onReceive() was being fired by an scheduled intent.

This meant that the PendingIntents were overriding their place in the AlarmManager queue by using the same requestCode.
This also explains why this queue was being filled on app start each time.

Here is a small glance into the logs in this reddit post I made, in which I could positively confirmed that the IntentManager behind the AlarmManager is persisting the scheduled Intents upon App closing.

This means that the queue inside the project's AlarmScheduler was not needed. and so, the bug fixes itself by getting rid of this queue.

As I said, there must be a reason of the why that queue is being used, and I guess it's because this id persistence ability requires a different method of Intent scheduling for some Android version, that the code is not accounting for.

the main bug discussed in this report can be repeated by enabling a sequence of alarms (any number) BUT the FIRST and LAST must have the same exact time, use a time proximate to current time.

Of course, another alternative is changing the fireAlarmsInThePast() and allow the foreach consumer to fire JUST the alarms with repeating time, and not the ones in the middle.

@yuriykulikov
Copy link
Owner

Context

AlarmsScheduler maintains a queue of alarms sorted by their time. The head of the queue is also added as an alarm with AlarmsManager. When this alarm fires, the head is removed from the queue and is replaced with another alarm.

There are multiple reasons for using a queue in AlarmsScheduler.

  • Android has (or had) limitations on how many alarms one application can schedule within a time interval
  • Some vendors (like Samsung) have a hard limit on the amount of alarms
  • It helps with logging and testing

Bug

I assume the bug you are referring too occurs when the head and the next alarm are close to each other. It is possible that the issue can be fixed here:

 private fun fireAlarmsInThePast() {
    val now = calendars.now()
    while (!queue.isEmpty() && queue.peek()?.calendar?.before(now) == true) {
      // remove happens in fire
      queue.poll()?.let { firedInThePastAlarm ->
        log.warning { "In the past - $firedInThePastAlarm" }
        setter.fireNow(firedInThePastAlarm.id, firedInThePastAlarm.type.name)
      }
    }
  }

Impact

AlarmsScheduler can use some refactoring and tests, but I would limit the change to the class only.

@Skylarkarms
Copy link
Author

Absolutely agree with the fact that the changes were too drastic, I thought the scheduler behavior made it seem as if the alarms were supposed to stack inside the Manager, what was really happening is that they were being pushed to the queue stack, and only the head was the one being appointed to the Manager.
Thank you for the clarification.

I don't know If I should maybe close this. but I'll still do.

@Skylarkarms
Copy link
Author

I am so sorry to bother you, I just want to let you know that this entire bug was my own fault. I went back to see my changes and I placed some faulty references in order to Log things and in the process, I messed with the while loop:

This is so amateurish I am...

private fun fireAlarmsInThePast() {
    val now = calendars.now()
      val peeked : ScheduledAlarm? = queue.peek()
      val topIsBeforeNow = peeked?.calendar?.before(now)
//      val topIsBeforeNow = queue.peek()?.calendar?.before(now)
      Log.println(Log.ASSERT, TAG, "fireAlarmsInThePast: peeked = $peeked" +
          ",\n is before now? $topIsBeforeNow")
//As you can see the peek is not updated since it was referenced outside the loop....
    while (!queue.isEmpty() && topIsBeforeNow == true) {
      // remove happens in fire
      queue.poll()?.let { firedInThePastAlarm ->
//        log.warning { "In the past - $firedInThePastAlarm" }
        setter.fireNow(firedInThePastAlarm.id, firedInThePastAlarm.type.name)
      }
    }
  }

This means that my logged version was the one with the bug, not yours.

Please I beg your pardon for my mistake... 🙏

@yuriykulikov
Copy link
Owner

Hey @Skylarkarms,

thank you for clarifying this. I welcome discussions and contributions, so there is no need for excuses :)

BTW, looking at my code here:

 private fun fireAlarmsInThePast() {
    val now = calendars.now()
    while (!queue.isEmpty() && queue.peek()?.calendar?.before(now) == true) {
      // remove happens in fire
      queue.poll()?.let { firedInThePastAlarm ->
        log.warning { "In the past - $firedInThePastAlarm" }
        setter.fireNow(firedInThePastAlarm.id, firedInThePastAlarm.type.name)
      }
    }
  }

I can see that it definitely can benefit from a refactoring. It is hard to understand. If you want, you can try refactoring it and I will be glad to do a code review.

// remove happens in fire is definitely a red flag for me. I think this code should separate looking through the queue, removing items from the queue and firing alarms.
Let me know if you would like to give it a go.

If you are interested, there are also many items here: https://github.com/users/yuriykulikov/projects/2

@Skylarkarms
Copy link
Author

Hi @yuriykulikov Now that I think more clearly about this, the name of the field being "setter" I believe is self-explanatory.

I don't think programming syntax and semantics needs to be easy in order for programmers to understand more easily, but even if we use easy-to-interpret words, these words would still be hiding complex behavior behind these systems.

In this case the complexity relies in that the underlying Manager CAN handle scheduling, but because of the Android system's limitations... the project decided to hide it under a "setter" interface instead of an "addition/offering/scheduling/etc..." one.

So, if we are not aware of this minutiae it becomes harder to catch up, even on the significance of the simplest of words such as "setter" since they are bound to their vast context just to be able to understand.

This is why it is so difficult to make programming related questions (lol), but you immediately caught up on what I was missing.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants