derat
commented
1 year ago I saw this happen twice today and tried to capture bug reports. This is from when I initially saw it:
01-18 10:17:36.924 1000 2023 5160 D CompatibilityChangeReporter: Compat change id reported: 135634846; UID 10323; state: DISABLED
01-18 10:17:36.924 1000 2023 5160 D CompatibilityChangeReporter: Compat change id reported: 177438394; UID 10323; state: DISABLED
01-18 10:17:36.924 1000 2023 5160 D CompatibilityChangeReporter: Compat change id reported: 135772972; UID 10323; state: DISABLED
01-18 10:17:36.924 1000 2023 5160 D CompatibilityChangeReporter: Compat change id reported: 135754954; UID 10323; state: ENABLED
01-18 10:17:36.983 1000 2023 2278 D CompatibilityChangeReporter: Compat change id reported: 143937733; UID 10323; state: ENABLED
01-18 10:17:37.312 1000 2023 2278 I ActivityManager: Start proc 5650:org.erat.nup/u0a323 for service {org.erat.nup/org.erat.nup.NupService}
01-18 10:17:38.530 1000 2023 3264 D CompatibilityChangeReporter: Compat change id reported: 161145287; UID 10323; state: DISABLED
01-18 10:17:40.443 1000 2023 2023 I NotificationService: Cannot find enqueued record for key: 0|org.erat.nup|1|null|10323
01-18 10:17:40.450 1000 2023 5176 D CompatibilityChangeReporter: Compat change id reported: 161252188; UID 10323; state: ENABLED
01-18 10:17:40.464 1000 2023 5176 D CompatibilityChangeReporter: Compat change id reported: 168419799; UID 10323; state: DISABLED
01-18 10:17:47.616 10323 5650 5930 D FileCacheDatabase: Finished loading 2184 cache entries
01-18 10:17:47.773 10323 5650 5942 D SongDatabase: Learned about 2184 cached song(s)
01-18 10:17:47.778 10323 5650 5650 D NupService: Service created
01-18 10:17:47.800 10323 5650 5650 D NetworkHelper: Network initially available
01-18 10:17:47.994 10323 5650 6750 D FileCacheDatabase: Loading cache entries
01-18 10:17:48.176 10323 5650 5650 D NupService: Service destroyed
01-18 10:17:48.179 1000 2023 5662 I MediaFocusControl: abandonAudioFocus() from uid/pid 10323/5650 clientId=android.media.AudioManager@1267610org.erat.nup.NupService$$ExternalSyntheticLambda3@5b95509
01-18 10:17:50.475 10323 5650 6750 D FileCacheDatabase: Finished loading 2184 cache entries
01-18 10:17:51.956 10323 5650 5942 D SongDatabase: Learned about 2184 cached song(s)
01-18 10:17:51.963 10323 5650 5650 D NupService: Aggregate data updated
01-18 10:17:51.964 10323 5650 5650 D MediaBrowserHelper: Notifying about changes for song database update
01-18 10:17:51.975 10323 5650 5650 D NupService: Aggregate data updated
01-18 10:17:51.975 10323 5650 5650 D MediaBrowserHelper: Notifying about changes for song database update
01-18 10:18:06.398 lmkd 669 669 I lowmemorykiller: Kill 'org.erat.nup' (5650), uid 10323, oom_score_adj 975 to free 93680kB rss, 12976kB swap; reason: low watermark is breached and swap is low (28340kB < 209712kB)
01-18 10:18:06.479 1000 2023 2356 I libprocessgroup: Successfully killed process cgroup uid 10323 pid 5650 in 0ms
01-18 10:17:36.923 1000 2023 5160 I am_uid_running: 10323
01-18 10:17:37.312 1000 2023 2278 I am_proc_start: [0,5650,10323,org.erat.nup,service,{org.erat.nup/org.erat.nup.NupService}]
01-18 10:17:37.857 1000 2023 5176 I am_uid_active: 10323
01-18 10:17:39.366 1000 2023 5171 I am_foreground_service_start: [0,org.erat.nup/.NupService,1,PROC_STATE_PERSISTENT,33,33,0,0,0,1,UNKNOWN]
01-18 10:17:40.241 1000 2023 2023 I notification_enqueue: [10323,5650,org.erat.nup,1,NULL,0,Notification(channel=NupService shortcut=null contentView=null vibrate=null sound=null defaults=0x0 flags=0x42 color=0x00000000 category=transport vis=PUBLIC),0]
01-18 10:17:40.430 1000 2023 2023 I sysui_multi_action: [757,128,758,5,759,8,793,948,794,0,795,948,796,1,806,org.erat.nup,857,NupService,858,2,947,0,1500,948,1641,transport,1688,2,1745,1043716538]
01-18 10:17:40.430 1000 2023 2023 I notification_canceled: [0|org.erat.nup|1|null|10323,8,948,948,0,-1,-1,NULL]
01-18 10:17:40.436 1000 2023 2399 I am_foreground_service_stop: [0,org.erat.nup/.NupService,1,PROC_STATE_PERSISTENT,33,33,0,0,1070,1,STOP_SERVICE]Android bug reports are a complete mess and I have no idea what's going on. There are messages from the Player class at 10:20 but no log entries from 10:19, for example.
The service should've still been running the second time I saw this, but that bug report has even less useful information from the service. This seems suspicious:
01-18 11:27:56.263 1000 2023 6235 I MediaSessionService: tempAllowlistTargetPkgIfPossible callingPackage:com.google.android.projection.gearhead targetPackage:com.google.android.googlequicksearchbox reason:MediaSessionRecord:android.support.v4.media.session.command.GET_EXTRA_BINDER [WIU] [FGS]
01-18 11:27:56.282 1000 1459 1540 D CHRE : @ 2958695.582: [ActivityPlatform] type 4, confidence 67
01-18 11:27:56.324 10164 26514 26514 I GH.DefaultAppManager: component not validated, was null, category=MEDIA uiMode=PROJECTED
01-18 11:27:56.325 10164 26514 26514 I GH.DefaultAppManager: getDefaultApp clearing invalid component null MEDIA PROJECTED
01-18 11:27:56.326 10164 4591 4736 I GH.ConnLoggerV2: Session [redacted], event 59, detail null, FACET_BAR_FIRST_RESUME, at 2958689407
01-18 11:27:56.326 10164 4591 4736 I GH.StartupMeasure: logEvent GEARHEAD_FACET_BAR_FIRST_RESUME=2958689407
01-18 11:27:56.327 10164 26514 26514 I GH.DefaultAppManager: component not validated, was null, category=MEDIA uiMode=PROJECTED
01-18 11:27:56.327 10164 26514 26514 I GH.DefaultAppManager: getDefaultApp clearing invalid component null MEDIA PROJECTED
01-18 11:27:56.329 10164 26514 26514 I GH.MediaDefaultAppCtrl: Setting default media app to com.google.android.googlequicksearchbox/com.google.android.apps.search.podcasts.browser.PodcastBrowserService.Beats me, though. Maybe the new version of Android Auto will be less buggy.
Maybe 10-20% of the time when I start my car with my phone connected, Android Auto launches the Google Podcasts app instead of nup (and because Google Podcasts is apparently incapable of saving my progress, it typically autoplays in the middle of an already-completed podcast). I think that nup isn't listed in the head unit's menu when this happens, but it always shows up if I re-plug the phone (although I need to navigate back to the menu and launch it to make it replace Google Podcasts). Maybe there's some race where the service isn't responding quickly enough?