rename 'docs' directory to 'doc'
This commit is contained in:
251
doc/design/prefetch-scheduling-trace.md
Normal file
251
doc/design/prefetch-scheduling-trace.md
Normal file
@@ -0,0 +1,251 @@
|
||||
# Prefetch Scheduling Trace Analysis
|
||||
|
||||
**Analysis Date**: October 27, 2025 - 12:18:37 UTC
|
||||
**Author**: Matthew Raymer
|
||||
**Status**: Investigation Complete
|
||||
|
||||
## Summary
|
||||
|
||||
This document traces how prefetch scheduling works solo and in conjunction with notification schedules. Investigation reveals that **prefetch schedules ARE being set**, but there may be issues with logging visibility and execution.
|
||||
|
||||
## Code Flow Analysis
|
||||
|
||||
### 1. Notification Scheduling Flow
|
||||
|
||||
When a user schedules a notification via the plugin:
|
||||
|
||||
```
|
||||
DailyNotificationPlugin.scheduleDailyNotification()
|
||||
↓
|
||||
DailyNotificationScheduler.scheduleNotification()
|
||||
↓
|
||||
Plugin.scheduleBackgroundFetch(content.getScheduledTime())
|
||||
```
|
||||
|
||||
**Location**: `android/plugin/src/main/java/com/timesafari/dailynotification/DailyNotificationPlugin.java:658`
|
||||
|
||||
### 2. Prefetch Scheduling Flow
|
||||
|
||||
The `scheduleBackgroundFetch` method calculates the fetch time:
|
||||
|
||||
```java
|
||||
private void scheduleBackgroundFetch(long scheduledTime) {
|
||||
try {
|
||||
Log.d(TAG, "DN|SCHEDULE_FETCH_START time=" + scheduledTime);
|
||||
|
||||
// Schedule fetch 5 minutes before notification
|
||||
long fetchTime = scheduledTime - TimeUnit.MINUTES.toMillis(5);
|
||||
|
||||
if (fetchTime > System.currentTimeMillis()) {
|
||||
Log.d(TAG, "DN|SCHEDULE_FETCH_CALC fetch_at=" + fetchTime + " notification_at=" + scheduledTime);
|
||||
fetcher.scheduleFetch(fetchTime);
|
||||
Log.i(TAG, "DN|SCHEDULE_FETCH_OK Background fetch scheduled for " + fetchTime + " (5 minutes before notification at " + scheduledTime + ")");
|
||||
} else {
|
||||
Log.w(TAG, "DN|SCHEDULE_FETCH_PAST fetch_time=" + fetchTime + " current=" + System.currentTimeMillis());
|
||||
}
|
||||
} catch (Exception e) {
|
||||
Log.e(TAG, "DN|SCHEDULE_FETCH_ERR Error scheduling background fetch", e);
|
||||
}
|
||||
}
|
||||
```
|
||||
|
||||
**Location**: `DailyNotificationPlugin.java:961-978`
|
||||
|
||||
### 3. WorkManager Enqueuing
|
||||
|
||||
The `fetcher.scheduleFetch()` method creates a WorkManager request:
|
||||
|
||||
```java
|
||||
public void scheduleFetch(long scheduledTime) {
|
||||
try {
|
||||
Log.d(TAG, "Scheduling background fetch for " + scheduledTime);
|
||||
|
||||
// Calculate fetch time (5 minutes before notification)
|
||||
long fetchTime = scheduledTime - TimeUnit.MINUTES.toMillis(5);
|
||||
|
||||
if (fetchTime > System.currentTimeMillis()) {
|
||||
// Create work data
|
||||
Data inputData = new Data.Builder()
|
||||
.putLong("scheduled_time", scheduledTime)
|
||||
.putLong("fetch_time", fetchTime)
|
||||
.putInt("retry_count", 0)
|
||||
.build();
|
||||
|
||||
// Create one-time work request
|
||||
OneTimeWorkRequest fetchWork = new OneTimeWorkRequest.Builder(
|
||||
DailyNotificationFetchWorker.class)
|
||||
.setInputData(inputData)
|
||||
.addTag(WORK_TAG_FETCH)
|
||||
.setInitialDelay(fetchTime - System.currentTimeMillis(), TimeUnit.MILLISECONDS)
|
||||
.build();
|
||||
|
||||
// Enqueue the work
|
||||
workManager.enqueue(fetchWork);
|
||||
|
||||
Log.i(TAG, "Background fetch scheduled successfully");
|
||||
|
||||
} else {
|
||||
Log.w(TAG, "Fetch time has already passed, scheduling immediate fetch");
|
||||
scheduleImmediateFetch();
|
||||
}
|
||||
|
||||
} catch (Exception e) {
|
||||
Log.e(TAG, "Error scheduling background fetch", e);
|
||||
// Fallback to immediate fetch
|
||||
scheduleImmediateFetch();
|
||||
}
|
||||
}
|
||||
```
|
||||
|
||||
**Location**: `DailyNotificationFetcher.java:77-115`
|
||||
|
||||
## Key Findings
|
||||
|
||||
### ✅ Prefetch Scheduling IS Implemented
|
||||
|
||||
The code shows that:
|
||||
|
||||
1. **When a notification is scheduled**, `scheduleBackgroundFetch()` is called **if scheduling succeeds**
|
||||
2. **The prefetch time is calculated**: `fetchTime = scheduledTime - 5 minutes`
|
||||
3. **WorkManager work is enqueued** with the calculated delay
|
||||
4. **Logs ARE generated** at several points
|
||||
|
||||
### ⚠️ Potential Issues
|
||||
|
||||
1. **Logging Visibility**
|
||||
- Logs may not be visible if:
|
||||
- The app is closed (logs go to system logcat)
|
||||
- Filters are not capturing the right tags
|
||||
- Log level is not set correctly
|
||||
|
||||
2. **Conditional Logging**
|
||||
- The `scheduleBackgroundFetch` is only called when `scheduled == true`
|
||||
- If notification scheduling fails, no prefetch is scheduled
|
||||
- This is at line 655-666 in `DailyNotificationPlugin.java`
|
||||
|
||||
3. **Timing Issues**
|
||||
- If `fetchTime` is in the past, it schedules immediate fetch
|
||||
- This might cause confusion if timing calculations are wrong
|
||||
|
||||
## Expected Log Sequence
|
||||
|
||||
When properly scheduling a notification:
|
||||
|
||||
```
|
||||
DN|SCHEDULE_CALLBACK scheduled=true, calling scheduleBackgroundFetch
|
||||
DN|SCHEDULE_FETCH_START time=<scheduledTime>
|
||||
DN|SCHEDULE_FETCH_CALC fetch_at=<fetchTime> notification_at=<scheduledTime>
|
||||
Scheduling background fetch for <scheduledTime>
|
||||
Background fetch scheduled successfully
|
||||
DN|SCHEDULE_FETCH_OK Background fetch scheduled for <fetchTime> (5 minutes before notification at <scheduledTime>)
|
||||
```
|
||||
|
||||
## How to Debug
|
||||
|
||||
### 1. Check if Prefetch is Being Scheduled
|
||||
|
||||
Look for these log tags in logcat:
|
||||
|
||||
```bash
|
||||
adb logcat | grep -E "DN\|SCHEDULE_FETCH|DailyNotificationFetcher"
|
||||
```
|
||||
|
||||
Expected logs:
|
||||
- `DN|SCHEDULE_FETCH_START`
|
||||
- `DN|SCHEDULE_FETCH_CALC`
|
||||
- `DN|SCHEDULE_FETCH_OK`
|
||||
- `Scheduling background fetch for`
|
||||
|
||||
### 2. Check WorkManager Queue
|
||||
|
||||
Verify that work is actually enqueued:
|
||||
|
||||
```bash
|
||||
adb shell dumpsys job scheduler | grep -A 5 "daily_notification_fetch"
|
||||
```
|
||||
|
||||
### 3. Check if Notification Scheduling Succeeded
|
||||
|
||||
Verify the notification scheduling succeeded (this is a prerequisite):
|
||||
|
||||
```bash
|
||||
adb logcat | grep "DN|SCHEDULE"
|
||||
```
|
||||
|
||||
Look for:
|
||||
- `DN|SCHEDULE_CALLBACK scheduled=true` - **Good**, prefetch will be scheduled
|
||||
- `DN|SCHEDULE_CALLBACK scheduled=false` - **Bad**, prefetch will NOT be scheduled
|
||||
|
||||
### 4. Check AlarmManager Schedule
|
||||
|
||||
Verify the actual alarm is set:
|
||||
|
||||
```bash
|
||||
adb shell dumpsys alarm | grep -i "dailynotification"
|
||||
```
|
||||
|
||||
## Investigation Checklist
|
||||
|
||||
To diagnose why prefetch logs aren't appearing:
|
||||
|
||||
- [ ] Check if notification scheduling is succeeding (look for `DN|SCHEDULE_CALLBACK scheduled=true`)
|
||||
- [ ] Check if `scheduleBackgroundFetch` is being called (look for `DN|SCHEDULE_FETCH_START`)
|
||||
- [ ] Check if fetch time calculation is correct (look for `DN|SCHEDULE_FETCH_CALC`)
|
||||
- [ ] Check if WorkManager is enqueuing the work (look for "Background fetch scheduled successfully")
|
||||
- [ ] Check if fetch time is in the past (look for "Fetch time has already passed")
|
||||
- [ ] Check WorkManager queue status via `dumpsys job scheduler`
|
||||
- [ ] Check for any exceptions (look for "DN|SCHEDULE_FETCH_ERR" or "Error scheduling background fetch")
|
||||
|
||||
## Recommendations
|
||||
|
||||
### 1. Add More Diagnostic Logging
|
||||
|
||||
Add logs at critical decision points:
|
||||
|
||||
```java
|
||||
// In scheduleDailyNotification, after scheduler.scheduleNotification()
|
||||
if (scheduled) {
|
||||
Log.i(TAG, "DN|SCHEDULE_CALLBACK scheduled=true, calling scheduleBackgroundFetch");
|
||||
Log.d(TAG, "DN|SCHEDULE_CALLBACK content.getScheduledTime()=" + content.getScheduledTime());
|
||||
scheduleBackgroundFetch(content.getScheduledTime());
|
||||
} else {
|
||||
Log.w(TAG, "DN|SCHEDULE_CALLBACK scheduled=false, NOT calling scheduleBackgroundFetch");
|
||||
}
|
||||
```
|
||||
|
||||
### 2. Add WorkManager Status Logging
|
||||
|
||||
Add a log after enqueuing to verify:
|
||||
|
||||
```java
|
||||
workManager.enqueue(fetchWork);
|
||||
Log.i(TAG, "DN|SCHEDULE_WORK_ENQUEUED work_id=" + fetchWork.getId() +
|
||||
" fetch_at=" + fetchTime + " delay_ms=" + (fetchTime - System.currentTimeMillis()));
|
||||
```
|
||||
|
||||
### 3. Add User-Zero Specific Logging
|
||||
|
||||
For stars querying, add specific event IDs:
|
||||
|
||||
```java
|
||||
Log.i(TAG, "EVT_PREFETCH_SCHEDULED time=" + fetchTime + " stars_query=true");
|
||||
```
|
||||
|
||||
## Next Steps
|
||||
|
||||
1. **Capture logcat** during notification scheduling
|
||||
2. **Search for specific log prefixes** documented above
|
||||
3. **Check WorkManager queue** to verify work is enqueued
|
||||
4. **Add diagnostic logging** if needed
|
||||
5. **Test with actual notification scheduling** to see full flow
|
||||
|
||||
## Conclusion
|
||||
|
||||
The prefetch scheduling **IS implemented** in the codebase. The issue is likely one of:
|
||||
|
||||
- Logging visibility (logs not being captured)
|
||||
- Timing issues (fetch time in past)
|
||||
- Notification scheduling failure (prefetch not called)
|
||||
- WorkManager not executing (system-level issue)
|
||||
|
||||
The infrastructure is there, but we need to verify the execution path.
|
||||
Reference in New Issue
Block a user