feat(android): Add instrumentation logs for prefetch investigation
Add comprehensive instrumentation to diagnose why native fetcher is not being called during prefetch operations. Instrumentation Added: - TimeSafariApplication: Log app initialization, fetcher registration, and verification with process ID and timestamps - TimeSafariNativeFetcher: Log configuration, fetch start, source resolution (native vs fallback), and write completion - Diagnostic script: Filter logcat for prefetch-related events - Investigation summary: Document root cause hypotheses and diagnostic checklist Log Tags: - APP|ON_CREATE: App initialization timing and process info - FETCHER|REGISTER_START/REGISTERED: Fetcher registration lifecycle - FETCHER|CONFIGURE_START/CONFIGURE_COMPLETE: Configuration tracking - PREFETCH|START/SOURCE/WRITE_OK: Prefetch operation tracking - DISPLAY|START/LOOKUP: Display worker tracking (future) - STORAGE|POST_PREFETCH/PRE_DISPLAY: Storage verification (future) This instrumentation will help diagnose: 1. Registration timing issues (worker before onCreate) 2. Fetcher resolution failures (null fetcher) 3. Process mismatches (multi-process issues) 4. ID schema inconsistencies (prefetch vs display) 5. Storage persistence issues (content not saved) Author: Matthew Raymer
This commit is contained in:
@@ -27,14 +27,44 @@ public class TimeSafariApplication extends Application {
|
|||||||
public void onCreate() {
|
public void onCreate() {
|
||||||
super.onCreate();
|
super.onCreate();
|
||||||
|
|
||||||
|
// Instrumentation: Log app initialization with process info
|
||||||
|
int pid = android.os.Process.myPid();
|
||||||
|
String processName = getApplicationInfo().processName;
|
||||||
|
Log.i(TAG, String.format(
|
||||||
|
"APP|ON_CREATE ts=%d pid=%d processName=%s",
|
||||||
|
System.currentTimeMillis(),
|
||||||
|
pid,
|
||||||
|
processName
|
||||||
|
));
|
||||||
|
|
||||||
Log.i(TAG, "Initializing TimeSafari Application");
|
Log.i(TAG, "Initializing TimeSafari Application");
|
||||||
|
|
||||||
// Register native fetcher with application context
|
// Register native fetcher with application context
|
||||||
Context context = getApplicationContext();
|
Context context = getApplicationContext();
|
||||||
NativeNotificationContentFetcher nativeFetcher =
|
NativeNotificationContentFetcher nativeFetcher =
|
||||||
new TimeSafariNativeFetcher(context);
|
new TimeSafariNativeFetcher(context);
|
||||||
|
|
||||||
|
// Instrumentation: Log before registration
|
||||||
|
Log.i(TAG, String.format(
|
||||||
|
"FETCHER|REGISTER_START instanceHash=%d ts=%d",
|
||||||
|
nativeFetcher.hashCode(),
|
||||||
|
System.currentTimeMillis()
|
||||||
|
));
|
||||||
|
|
||||||
DailyNotificationPlugin.setNativeFetcher(nativeFetcher);
|
DailyNotificationPlugin.setNativeFetcher(nativeFetcher);
|
||||||
|
|
||||||
|
// Instrumentation: Verify registration succeeded
|
||||||
|
NativeNotificationContentFetcher verified =
|
||||||
|
DailyNotificationPlugin.getNativeFetcherStatic();
|
||||||
|
boolean registered = (verified != null && verified == nativeFetcher);
|
||||||
|
|
||||||
|
Log.i(TAG, String.format(
|
||||||
|
"FETCHER|REGISTERED providerKey=DailyNotificationPlugin instanceHash=%d registered=%s ts=%d",
|
||||||
|
nativeFetcher.hashCode(),
|
||||||
|
registered,
|
||||||
|
System.currentTimeMillis()
|
||||||
|
));
|
||||||
|
|
||||||
Log.i(TAG, "Native fetcher registered: " + nativeFetcher.getClass().getName());
|
Log.i(TAG, "Native fetcher registered: " + nativeFetcher.getClass().getName());
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|||||||
@@ -92,10 +92,31 @@ public class TimeSafariNativeFetcher implements NativeNotificationContentFetcher
|
|||||||
*/
|
*/
|
||||||
@Override
|
@Override
|
||||||
public void configure(String apiBaseUrl, String activeDid, String jwtToken) {
|
public void configure(String apiBaseUrl, String activeDid, String jwtToken) {
|
||||||
|
// Instrumentation: Log configuration start
|
||||||
|
int pid = android.os.Process.myPid();
|
||||||
|
Log.i(TAG, String.format(
|
||||||
|
"FETCHER|CONFIGURE_START instanceHash=%d pid=%d ts=%d",
|
||||||
|
this.hashCode(),
|
||||||
|
pid,
|
||||||
|
System.currentTimeMillis()
|
||||||
|
));
|
||||||
|
|
||||||
this.apiBaseUrl = apiBaseUrl;
|
this.apiBaseUrl = apiBaseUrl;
|
||||||
this.activeDid = activeDid;
|
this.activeDid = activeDid;
|
||||||
this.jwtToken = jwtToken;
|
this.jwtToken = jwtToken;
|
||||||
|
|
||||||
|
// Instrumentation: Log configuration completion
|
||||||
|
boolean configured = (apiBaseUrl != null && activeDid != null && jwtToken != null);
|
||||||
|
Log.i(TAG, String.format(
|
||||||
|
"FETCHER|CONFIGURE_COMPLETE instanceHash=%d configured=%s apiBaseUrl=%s activeDid=%s jwtLength=%d ts=%d",
|
||||||
|
this.hashCode(),
|
||||||
|
configured,
|
||||||
|
apiBaseUrl != null ? apiBaseUrl : "null",
|
||||||
|
activeDid != null ? activeDid.substring(0, Math.min(30, activeDid.length())) + "..." : "null",
|
||||||
|
jwtToken != null ? jwtToken.length() : 0,
|
||||||
|
System.currentTimeMillis()
|
||||||
|
));
|
||||||
|
|
||||||
// Enhanced logging for JWT diagnostic purposes
|
// Enhanced logging for JWT diagnostic purposes
|
||||||
Log.i(TAG, "TimeSafariNativeFetcher: Configured with API: " + apiBaseUrl);
|
Log.i(TAG, "TimeSafariNativeFetcher: Configured with API: " + apiBaseUrl);
|
||||||
if (activeDid != null) {
|
if (activeDid != null) {
|
||||||
@@ -122,6 +143,18 @@ public class TimeSafariNativeFetcher implements NativeNotificationContentFetcher
|
|||||||
public CompletableFuture<List<NotificationContent>> fetchContent(
|
public CompletableFuture<List<NotificationContent>> fetchContent(
|
||||||
@NonNull FetchContext context) {
|
@NonNull FetchContext context) {
|
||||||
|
|
||||||
|
// Instrumentation: Log fetch start with context
|
||||||
|
int pid = android.os.Process.myPid();
|
||||||
|
Log.i(TAG, String.format(
|
||||||
|
"PREFETCH|START id=%s notifyAt=%d trigger=%s instanceHash=%d pid=%d ts=%d",
|
||||||
|
context.scheduledTime != null ? "daily_" + context.scheduledTime : "unknown",
|
||||||
|
context.scheduledTime != null ? context.scheduledTime : 0,
|
||||||
|
context.trigger,
|
||||||
|
this.hashCode(),
|
||||||
|
pid,
|
||||||
|
System.currentTimeMillis()
|
||||||
|
));
|
||||||
|
|
||||||
Log.d(TAG, "TimeSafariNativeFetcher: Fetch triggered - trigger=" + context.trigger +
|
Log.d(TAG, "TimeSafariNativeFetcher: Fetch triggered - trigger=" + context.trigger +
|
||||||
", scheduledTime=" + context.scheduledTime + ", fetchTime=" + context.fetchTime);
|
", scheduledTime=" + context.scheduledTime + ", fetchTime=" + context.fetchTime);
|
||||||
|
|
||||||
@@ -143,10 +176,25 @@ public class TimeSafariNativeFetcher implements NativeNotificationContentFetcher
|
|||||||
try {
|
try {
|
||||||
// Check if configured
|
// Check if configured
|
||||||
if (apiBaseUrl == null || activeDid == null || jwtToken == null) {
|
if (apiBaseUrl == null || activeDid == null || jwtToken == null) {
|
||||||
|
Log.e(TAG, String.format(
|
||||||
|
"PREFETCH|SOURCE from=fallback reason=not_configured apiBaseUrl=%s activeDid=%s jwtToken=%s ts=%d",
|
||||||
|
apiBaseUrl != null ? "set" : "null",
|
||||||
|
activeDid != null ? "set" : "null",
|
||||||
|
jwtToken != null ? "set" : "null",
|
||||||
|
System.currentTimeMillis()
|
||||||
|
));
|
||||||
Log.e(TAG, "TimeSafariNativeFetcher: Not configured. Call configureNativeFetcher() from TypeScript first.");
|
Log.e(TAG, "TimeSafariNativeFetcher: Not configured. Call configureNativeFetcher() from TypeScript first.");
|
||||||
return Collections.emptyList();
|
return Collections.emptyList();
|
||||||
}
|
}
|
||||||
|
|
||||||
|
// Instrumentation: Log native fetcher usage
|
||||||
|
Log.i(TAG, String.format(
|
||||||
|
"PREFETCH|SOURCE from=native instanceHash=%d apiBaseUrl=%s ts=%d",
|
||||||
|
this.hashCode(),
|
||||||
|
apiBaseUrl,
|
||||||
|
System.currentTimeMillis()
|
||||||
|
));
|
||||||
|
|
||||||
Log.i(TAG, "TimeSafariNativeFetcher: Starting fetch from " + apiBaseUrl + ENDORSER_ENDPOINT);
|
Log.i(TAG, "TimeSafariNativeFetcher: Starting fetch from " + apiBaseUrl + ENDORSER_ENDPOINT);
|
||||||
|
|
||||||
// Build request URL
|
// Build request URL
|
||||||
@@ -226,6 +274,14 @@ public class TimeSafariNativeFetcher implements NativeNotificationContentFetcher
|
|||||||
Log.i(TAG, "TimeSafariNativeFetcher: Successfully fetched " + contents.size() +
|
Log.i(TAG, "TimeSafariNativeFetcher: Successfully fetched " + contents.size() +
|
||||||
" notification(s)");
|
" notification(s)");
|
||||||
|
|
||||||
|
// Instrumentation: Log successful fetch
|
||||||
|
Log.i(TAG, String.format(
|
||||||
|
"PREFETCH|WRITE_OK id=%s items=%d ts=%d",
|
||||||
|
context.scheduledTime != null ? "daily_" + context.scheduledTime : "unknown",
|
||||||
|
contents.size(),
|
||||||
|
System.currentTimeMillis()
|
||||||
|
));
|
||||||
|
|
||||||
return contents;
|
return contents;
|
||||||
|
|
||||||
} else {
|
} else {
|
||||||
|
|||||||
109
docs/prefetch-investigation-summary.md
Normal file
109
docs/prefetch-investigation-summary.md
Normal file
@@ -0,0 +1,109 @@
|
|||||||
|
# Prefetch Investigation Summary
|
||||||
|
|
||||||
|
## Problem Statement
|
||||||
|
|
||||||
|
The daily notification prefetch job (T-5 min) is not calling the native fetcher, resulting in:
|
||||||
|
- `from: null` in prefetch logs
|
||||||
|
- Fallback/mock content being used
|
||||||
|
- `DISPLAY_SKIP content_not_found` at notification time
|
||||||
|
- Storage empty (`[]`) when display worker runs
|
||||||
|
|
||||||
|
## Root Cause Hypothesis
|
||||||
|
|
||||||
|
Based on the directive analysis, likely causes (ranked):
|
||||||
|
|
||||||
|
1. **Registration Timing**: Prefetch worker runs before `Application.onCreate()` completes
|
||||||
|
2. **Discovery Failure**: Worker resolves fetcher to `null` (wrong scope, process mismatch)
|
||||||
|
3. **Persistence Bug**: Content written but wiped/deduped before display
|
||||||
|
4. **ID Mismatch**: Prefetch writes `notify_...` but display looks for `daily_...`
|
||||||
|
|
||||||
|
## Instrumentation Added
|
||||||
|
|
||||||
|
### TimeSafariApplication.java
|
||||||
|
- `APP|ON_CREATE ts=... pid=... processName=...` - App initialization timing
|
||||||
|
- `FETCHER|REGISTER_START instanceHash=... ts=...` - Before registration
|
||||||
|
- `FETCHER|REGISTERED providerKey=... instanceHash=... registered=... ts=...` - After registration with verification
|
||||||
|
|
||||||
|
### TimeSafariNativeFetcher.java
|
||||||
|
- `FETCHER|CONFIGURE_START instanceHash=... pid=... ts=...` - Configuration start
|
||||||
|
- `FETCHER|CONFIGURE_COMPLETE instanceHash=... configured=... apiBaseUrl=... activeDid=... jwtLength=... ts=...` - Configuration completion
|
||||||
|
- `PREFETCH|START id=... notifyAt=... trigger=... instanceHash=... pid=... ts=...` - Fetch start
|
||||||
|
- `PREFETCH|SOURCE from=native/fallback reason=... ts=...` - Source resolution
|
||||||
|
- `PREFETCH|WRITE_OK id=... items=... ts=...` - Successful fetch
|
||||||
|
|
||||||
|
## Diagnostic Tools
|
||||||
|
|
||||||
|
### Log Filtering Script
|
||||||
|
```bash
|
||||||
|
./scripts/diagnose-prefetch.sh app.timesafari.app
|
||||||
|
```
|
||||||
|
|
||||||
|
Filters logcat for:
|
||||||
|
- `APP|ON_CREATE`
|
||||||
|
- `FETCHER|*`
|
||||||
|
- `PREFETCH|*`
|
||||||
|
- `DISPLAY|*`
|
||||||
|
- `STORAGE|*`
|
||||||
|
|
||||||
|
### Manual Filtering
|
||||||
|
```bash
|
||||||
|
adb logcat | grep -E "APP\|ON_CREATE|FETCHER\||PREFETCH\||DISPLAY\||STORAGE\|"
|
||||||
|
```
|
||||||
|
|
||||||
|
## Investigation Checklist
|
||||||
|
|
||||||
|
### A. App/Plugin Initialization Order
|
||||||
|
- [ ] Confirm `APP|ON_CREATE` appears before `PREFETCH|START`
|
||||||
|
- [ ] Verify `FETCHER|REGISTERED registered=true`
|
||||||
|
- [ ] Check for multiple `onCreate` invocations (process restarts)
|
||||||
|
- [ ] Confirm single process (no `android:process` on workers)
|
||||||
|
|
||||||
|
### B. Prefetch Worker Resolution
|
||||||
|
- [ ] Check `PREFETCH|SOURCE from=native` (not `from=fallback`)
|
||||||
|
- [ ] Verify `instanceHash` matches between registration and fetch
|
||||||
|
- [ ] Compare `pid` values (should be same process)
|
||||||
|
- [ ] Check `FETCHER|CONFIGURE_COMPLETE configured=true` before prefetch
|
||||||
|
|
||||||
|
### C. Storage & Persistence
|
||||||
|
- [ ] Verify `PREFETCH|WRITE_OK items>=1`
|
||||||
|
- [ ] Check storage logs for content persistence
|
||||||
|
- [ ] Compare prefetch ID vs display lookup ID (must match)
|
||||||
|
|
||||||
|
### D. ID Schema Consistency
|
||||||
|
- [ ] Prefetch ID format: `daily_<epoch>` or `notify_<epoch>`
|
||||||
|
- [ ] Display lookup ID format: must match prefetch ID
|
||||||
|
- [ ] Verify ID derivation rules are consistent
|
||||||
|
|
||||||
|
## Next Steps
|
||||||
|
|
||||||
|
1. **Run diagnostic script** during a notification cycle
|
||||||
|
2. **Analyze logs** for timing issues and process mismatches
|
||||||
|
3. **If fetcher is null**: Implement Fix #2 (Pass Fetcher Context With Work) or Fix #3 (Process-Safe DI)
|
||||||
|
4. **If ID mismatch**: Normalize ID schema across prefetch and display
|
||||||
|
5. **If storage issue**: Add transactional writes and read-after-write verification
|
||||||
|
|
||||||
|
## Expected Log Flow (Success Case)
|
||||||
|
|
||||||
|
```
|
||||||
|
APP|ON_CREATE ts=... pid=... processName=app.timesafari.app
|
||||||
|
FETCHER|REGISTER_START instanceHash=... ts=...
|
||||||
|
FETCHER|REGISTERED providerKey=DailyNotificationPlugin instanceHash=... registered=true ts=...
|
||||||
|
FETCHER|CONFIGURE_START instanceHash=... pid=... ts=...
|
||||||
|
FETCHER|CONFIGURE_COMPLETE instanceHash=... configured=true ... ts=...
|
||||||
|
PREFETCH|START id=daily_... notifyAt=... trigger=prefetch instanceHash=... pid=... ts=...
|
||||||
|
PREFETCH|SOURCE from=native instanceHash=... apiBaseUrl=... ts=...
|
||||||
|
PREFETCH|WRITE_OK id=daily_... items=1 ts=...
|
||||||
|
STORAGE|POST_PREFETCH total=1 ids=[daily_...]
|
||||||
|
DISPLAY|START id=daily_...
|
||||||
|
STORAGE|PRE_DISPLAY total=1 ids=[daily_...]
|
||||||
|
DISPLAY|LOOKUP result=hit id=daily_...
|
||||||
|
```
|
||||||
|
|
||||||
|
## Failure Indicators
|
||||||
|
|
||||||
|
- `PREFETCH|SOURCE from=fallback` - Native fetcher not resolved
|
||||||
|
- `PREFETCH|SOURCE from=null` - Fetcher registration failed
|
||||||
|
- `FETCHER|REGISTERED registered=false` - Registration verification failed
|
||||||
|
- `STORAGE|PRE_DISPLAY total=0` - Content not persisted
|
||||||
|
- `DISPLAY|LOOKUP result=miss` - ID mismatch or content cleared
|
||||||
|
|
||||||
36
scripts/diagnose-prefetch.sh
Executable file
36
scripts/diagnose-prefetch.sh
Executable file
@@ -0,0 +1,36 @@
|
|||||||
|
#!/bin/bash
|
||||||
|
#
|
||||||
|
# Diagnostic script for daily notification prefetch issues
|
||||||
|
# Filters logcat output for prefetch-related instrumentation logs
|
||||||
|
#
|
||||||
|
# Usage:
|
||||||
|
# ./scripts/diagnose-prefetch.sh [package_name]
|
||||||
|
#
|
||||||
|
# Example:
|
||||||
|
# ./scripts/diagnose-prefetch.sh app.timesafari.app
|
||||||
|
#
|
||||||
|
|
||||||
|
set -e
|
||||||
|
|
||||||
|
PACKAGE_NAME="${1:-app.timesafari.app}"
|
||||||
|
|
||||||
|
echo "🔍 Daily Notification Prefetch Diagnostic Tool"
|
||||||
|
echo "=============================================="
|
||||||
|
echo ""
|
||||||
|
echo "Package: $PACKAGE_NAME"
|
||||||
|
echo "Filtering for instrumentation tags:"
|
||||||
|
echo " - APP|ON_CREATE"
|
||||||
|
echo " - FETCHER|*"
|
||||||
|
echo " - PREFETCH|*"
|
||||||
|
echo " - DISPLAY|*"
|
||||||
|
echo " - STORAGE|*"
|
||||||
|
echo ""
|
||||||
|
echo "Press Ctrl+C to stop"
|
||||||
|
echo ""
|
||||||
|
|
||||||
|
# Filter logcat for instrumentation tags
|
||||||
|
adb logcat -c # Clear logcat buffer first
|
||||||
|
|
||||||
|
adb logcat | grep -E "APP\|ON_CREATE|FETCHER\||PREFETCH\||DISPLAY\||STORAGE\||DailyNotification|TimeSafariApplication|TimeSafariNativeFetcher" | \
|
||||||
|
grep -i "$PACKAGE_NAME\|TimeSafari\|DailyNotification"
|
||||||
|
|
||||||
Reference in New Issue
Block a user