From 28a825a46001ec8b44ed8344168301e3e2677c5d Mon Sep 17 00:00:00 2001 From: Matthew Raymer Date: Tue, 11 Nov 2025 05:05:10 +0000 Subject: [PATCH] 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 --- .../app/timesafari/TimeSafariApplication.java | 30 +++++ .../timesafari/TimeSafariNativeFetcher.java | 56 +++++++++ docs/prefetch-investigation-summary.md | 109 ++++++++++++++++++ scripts/diagnose-prefetch.sh | 36 ++++++ 4 files changed, 231 insertions(+) create mode 100644 docs/prefetch-investigation-summary.md create mode 100755 scripts/diagnose-prefetch.sh diff --git a/android/app/src/main/java/app/timesafari/TimeSafariApplication.java b/android/app/src/main/java/app/timesafari/TimeSafariApplication.java index e1160502..8c14b3b0 100644 --- a/android/app/src/main/java/app/timesafari/TimeSafariApplication.java +++ b/android/app/src/main/java/app/timesafari/TimeSafariApplication.java @@ -27,14 +27,44 @@ public class TimeSafariApplication extends Application { public void 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"); // Register native fetcher with application context Context context = getApplicationContext(); NativeNotificationContentFetcher nativeFetcher = 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); + // 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()); } } diff --git a/android/app/src/main/java/app/timesafari/TimeSafariNativeFetcher.java b/android/app/src/main/java/app/timesafari/TimeSafariNativeFetcher.java index 92928aba..2c631783 100644 --- a/android/app/src/main/java/app/timesafari/TimeSafariNativeFetcher.java +++ b/android/app/src/main/java/app/timesafari/TimeSafariNativeFetcher.java @@ -92,10 +92,31 @@ public class TimeSafariNativeFetcher implements NativeNotificationContentFetcher */ @Override 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.activeDid = activeDid; 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 Log.i(TAG, "TimeSafariNativeFetcher: Configured with API: " + apiBaseUrl); if (activeDid != null) { @@ -122,6 +143,18 @@ public class TimeSafariNativeFetcher implements NativeNotificationContentFetcher public CompletableFuture> fetchContent( @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 + ", scheduledTime=" + context.scheduledTime + ", fetchTime=" + context.fetchTime); @@ -143,10 +176,25 @@ public class TimeSafariNativeFetcher implements NativeNotificationContentFetcher try { // Check if configured 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."); 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); // Build request URL @@ -226,6 +274,14 @@ public class TimeSafariNativeFetcher implements NativeNotificationContentFetcher Log.i(TAG, "TimeSafariNativeFetcher: Successfully fetched " + contents.size() + " 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; } else { diff --git a/docs/prefetch-investigation-summary.md b/docs/prefetch-investigation-summary.md new file mode 100644 index 00000000..ed360695 --- /dev/null +++ b/docs/prefetch-investigation-summary.md @@ -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_` or `notify_` +- [ ] 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 + diff --git a/scripts/diagnose-prefetch.sh b/scripts/diagnose-prefetch.sh new file mode 100755 index 00000000..59e52f6e --- /dev/null +++ b/scripts/diagnose-prefetch.sh @@ -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" +