Missing ~ 50% of trips since July 23 2022

e-mission / e-mission-docs

Repository for docs and issues. If you need help, please file an issue here. Public conversations are better for open source projects than private email.

https://e-mission.readthedocs.io/en/latest

BSD 3-Clause "New" or "Revised" License

15 stars 34 forks source link

Missing ~ 50% of trips since July 23 2022 #774

Closed shankari closed 2 years ago

shankari commented 2 years ago

Since July 24, the app started abruptly dropping ~ 50% of my trips. It has close to 100% before that. Through obsessive checking, here are some high level observations:

we see the same behavior on my Motorola phone and on the test Motorola phone, both of which have SIM cards
the test Pixel phone, which does not have a SIM car, seems to detect even short trips

On the Motorola's, the geofence exit just does not trigger during the trip. And then, sometimes, it will trigger at the end of the trip. So we end up with a "point trip" at the end of the trip, which, depending on the length of the trip and the delay, is either ignored (common case), or is mapped as a Very Long Unknown mode trip directly from the start to the end.

This is the same version of CanBikeCO as I had before July 24, so it is not an app issue. I have been careful not to upgrade CanBikeCO. I do see periodic updates to both carrier services and Google Maps; not sure if they are related. Or whether the issue is related to Motorola phones.

I have both CanBikeCO and NREL OpenPATH installed and they both typically show the same behavior (both tracking or both not tracking). One one occasion, my daughter had an issue in which one of the apps was tracking and the other was not.

List of missing trips as of today (Aug 13):

Sat Jul 23: Trip to Downtown Palo Alto only recorded part from downtown PA to the train station
Mon Jul 25: Viola + Shopping only recorded after India Cash and Carry
Tue Jul 26: Blood draw only recorded trip back
Tue Jul 26: Karate only recorded trip there
Wed Jul 27: Karate completely missed trip
Wed Jul 27: walk around the block recorded perfectly
Thu Jul 28: Karate only recorded walk from parking location to Dojo
Sat Jul 30: Pick up Hari completely missed trip
Sun Jul 31: Drop off Hari only recorded trip back
Mon Aug 1: Viola recorded properly
Tue-Wed Aug 2-3: Camping trip; completely missed. turned tracking off and on
Wed Aug 3: Parent orientation only recorded trip back
Fri Aug 5: Shopping recorded perfectly
Sat Aug 6: Trip to Stanford Shopping Center recorded perfectly
Sun Aug 7: Stevenson Reunion only recorded trip there
Sun Aug 7: Trip to beach campground and beach recorded fairly perfectly
Mon Aug 8: Trip to beach and to first drop-off recorded fairly perfectly
Mon Aug 8: First to second drop-off had a big gap at the beginning but we were able to patch it with a straight line
Mon Aug 8: To viola recorded straight line
Mon Aug 8: From viola pretty perfect including walking from Trinethra to the library
Tue Aug 9: Karate only recorded trip there
Wed Aug 10: Hardware store; trip there was perfect, trip back apparently ended at Eagle Park
Thu Aug 11: Karate, only recorded trip back
Fri Aug 12: Library; trip there is a straight line (recorded as 4 hours), trip back is better
Sat Aug 13: Library, both trips are straight lines and the return trip ends on the opposite side of the street

shankari commented 2 years ago

High level observations:

walk is almost always detected
motorized transit is the worst (car/train)
when one half of a trip is skipped it is typically the trip there

That makes me think that maybe something changed wrt geofence responsiveness. In the car, we go so fast that we don't get the geofence exit. But while walking, we have a chance to catch up. But that doesn't explain:

the "straight line" library trips from yesterday and today which worked better on the test phone
the car trips that do work sometimes.

shankari commented 2 years ago

Let's start by focusing on the comparison between the test Pixel and my personal Motorola yesterday and today

system component	Personal phone	Test phone
Android version	10	12
Android security patch level	Aug 1, 2021	July 5, 2022
Google Play system update	2022-07-01 Q	July 1, 2022
Google Maps	Updated yesterday	Updated July 19
Carrier services	Updated 3 days ago	Updated 12:13am
CanBikeCO	May 1 (v1.3.3)	July 17 (v1.3.5)
NREL OpenPATH	??? updated	??? updated

To summarize, the Pixel has a more recent version of Android, but they both have the same version of Google Play Services. The carrier services also don't seem to be a problem, since both of them have been updated recently. Google Maps may be a potential culprit, but I am not sure I can roll back the change. And I am not sure I want to roll forward the change on the test phone until I have done more testing.

shankari commented 2 years ago

Other Motorola test phone also has Google Maps updated yesterday. Android patch level is still Aug 1, 2021. Google Play services is even older (2020-08-01). Finger seems to be pointing at Google Maps if anything.

Which is pretty sad, since that is not necessarily something I can control or roll back.

shankari commented 2 years ago

Digging deeper into Google Maps, I do see a difference in location accuracy between the motorolas and the pixel. But checking after an hour, the pixel has low accuracy too

Personal Motorola	Test Motorola	Test Pixel	Test Pixel after an hour

shankari commented 2 years ago

Location accuracy (pixel, personal)

10:40: Low, Low
8:30: Low, Low
12:30 High, Low
3:15: High, Low

But then when I took a trip to Palo Alto and back, the test phone didn't record properly and my personal phone did!

shankari commented 2 years ago

Will start with data since Friday since we have multiple examples of two phones, one of which tracks and the other doesn't, and the working/non-working status flips over time.

Friday to library: Test Pixel tracked, personal only got locations at the end
Saturday to library: Test Pixel tracked, personal only got locations at the end
Sunday to Palo Alto: Test Pixel only got locations at the end, personal tracked, except for ending the trip back home somewhere around El Camino and El Monte.

shankari commented 2 years ago

working pixel logs

Got geofence exit at 11:40, actually got three of them

08-12 11:40:06.654 10320 20489 20489 D GeofenceExitIntentService: onCreate called
08-12 11:40:06.664 10320 20489 25266 D GeofenceExitIntentService: Geofence exited! Intent = Intent { cmp=gov.nrel.cims.openpath/edu.berkeley.eecs.emission.cordova.tracker.location.GeofenceExitIntentService (has extras) } Starting ongoing monitoring...

Actually got 4 of them, probably for the 4 apps that I have installed on the test phone.

08-12 11:40:06.654 10320 20489 20489 D GeofenceExitIntentService: onCreate called
08-12 11:40:06.658 10281  5030  5030 D GeofenceExitIntentService: onCreate called
08-12 11:40:06.670 10268  5168  5168 D GeofenceExitIntentService: onCreate called
08-12 11:40:06.681 10291  5089  5089 D GeofenceExitIntentService: onCreate called

This seems to be in a section called --------- beginning of main

Looking for other geofence logs, we find a lot of geofence related pending intents

    #4: PendingIntentRecord{ccafe08 com.google.android.gms/com.google.android.gms.geotimezone broadcastIntent}
      uid=10190 packageName=com.google.android.gms featureId=com.google.android.gms.geotimezone type=broadcastIntent flags=0x2000000
      requestIntent=act=com.google.android.gms.geotimezone.GEOFENCE_FIRED pkg=com.google.android.gms

    #18: PendingIntentRecord{815f2b4 com.google.android.gms/geofencer_provider startService}
      uid=10190 packageName=com.google.android.gms featureId=geofencer_provider type=startService flags=0x2000000
      requestIntent=act=com.google.android.location.internal.action.GEOFENCER_LOCATION_RESULT pkg=com.google.android.gms cmp=com.google.android.gms/com.google.android.location.internal.PendingIntentCallbackService
      sent=true canceled=false

    #46: PendingIntentRecord{329619b com.google.android.gms/com.google.android.gms.contextmanager broadcastIntent}
      uid=10190 packageName=com.google.android.gms featureId=com.google.android.gms.contextmanager type=broadcastIntent flags=0x2000000
      requestIntent=act=android.gms.contextmanager.GEOFENCE

  * ReceiverList{71461cc 8854 com.google.android.gms.persistent/10190/u0 remote:1b47fff}
    app=8854:com.google.android.gms.persistent/u0a190 pid=8854 uid=10190 user=0
    Filter #0: BroadcastFilter{941fc15}
      Action: "com.google.android.gms.geotimezone.GEOFENCE_FIRED"

  * ReceiverList{ad93367 8854 com.google.android.gms.persistent/10190/u0 remote:dc77b26}
    app=8854:com.google.android.gms.persistent/u0a190 pid=8854 uid=10190 user=0
    Filter #0: BroadcastFilter{4ce7514}
      Action: "android.gms.contextmanager.NEARBY_ALERTS"
      Action: "android.gms.contextmanager.GEOFENCE"

Note that there needs to be related alert called NEARBY_ALERTS.

I also see other actions that might be related to detecting motion.

        android.gms.contextmanager.GEOFENCE:
        android.net.wifi.STATE_CHANGE:
        android.app.action.ENTER_CAR_MODE:
        android.app.action.EXIT_CAR_MODE:

And then there are some really interesting logs providing an indication of what the geofence is looking for. It is looking for the availability changed and the activity state.

    UniqueIds in use: 4
    Last location:
        Time=Fri Aug 12 11:44:42 PDT 2022
        Location[fused 37.391041,-122.086456 hAcc=5.184 et=+4h35m45s539ms alt=-4.799999713897705 vAcc=1.6442255 vel=0.0 sAcc=0.086023256 bear=90.0 {Bundle[mParcelledData.dataSize=312]}]
    Dump of hardware geofencing:
        Class is RealBlockingGeofenceHardware, monitoringType=0, limit=50
        Supported=true, available=true, enabled on this device=true
        Registered geofences:
        <none>
    Location update interval=300s
    Dump of ActivityDetector:
        Interval=180s
    Dump of current state:
        WalkingActivityState
    GeofencerStateMachine:
     total records=500
     rec[0]: time=08-12 11:44:42.471 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_LOCATION_AVAILABILITY_CHANGED
     rec[1]: time=08-12 11:44:42.471 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_LOCATION_AVAILABILITY_CHANGED
     rec[2]: time=08-12 11:44:42.575 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_LOCATION_CMD
     rec[3]: time=08-12 11:44:42.583 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_LOCATION_AVAILABILITY_CHANGED
     rec[4]: time=08-12 11:44:42.596 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_LOCATION_CMD
     rec[5]: time=08-12 11:44:42.647 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_LOCATION_CMD
     rec[6]: time=08-12 11:44:42.667 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_LOCATION_CMD
     rec[7]: time=08-12 11:44:42.682 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_LOCATION_CMD
     rec[8]: time=08-12 11:44:42.690 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_LOCATION_CMD
     rec[9]: time=08-12 11:44:43.284 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_LOCATION_CMD
    curState=WalkingActivityState
    LogRecords: capacity=200

This gives us another clue about reverse engineering the geofence manager.

    ### GeofencerDumpsysLogMessage END ###
    GeofencerStatsLogManager:
      Stats elapsed ms: 16453545
      GeofencerDeviceCapabilities:
        gps: supported(true), enabled(true)
        nlp: supported(true), enabled(true)
        significant_motion_detector: supported(true), enabled(false)
        gps_hardware_geofencing: supported(true), enabled(false)
        chre_geofencing: supported(true), enabled(false)
      Durations:
        WALKING_ACTIVITY enabled ms: 2670108
        HAS_GEOFENCE enabled ms: 188
        UNKNOWN_ACTIVITY enabled ms: 1045330
        NO_GEOFENCE enabled ms: 1855484
        NOT_INITIALIZED enabled ms: 266
        UNAVAILABLE_ACTIVITY enabled ms: 10425438
        STILL_ACTIVITY enabled ms: 453551
        current(WALKING_ACTIVITY) enabled ms: 3145
        Significant motion detector enabled ms: 0
          Currently disabled

shankari commented 2 years ago

Looking at the same logs for the personal phone...

No logs at 11:40, these are the earliest logs from main

--------- beginning of main
08-12 11:43:54.960 10279 10111 10352 D BuiltinUserCache: Query is SELECT * from userCache WHERE (type = 'message' OR type = 'rw-document' OR type = 'sensor-data') AND (write_ts <= 1.660329834576E9) ORDER BY write_ts LIMIT 10000
...
08-12 11:43:54.993 10298 30555 30555 I SensorControlBackgroundChecker: in restartFSMIfStartState, currState = local.state.waiting_for_trip_start
08-12 11:43:54.995 10279 10111 10111 D SensorControlBackgroundChecker: All settings valid, nothing to prompt

There was apparently a geofence exit at around 11:39, not sure why we didn't get it

  #245: act=local.transition.exited_geofence flg=0x10 pkg=gov.colorado.energyoffice.emission
    +22ms dispatch +116ms finish
    enq=2022-08-12 11:39:11.618 disp=2022-08-12 11:39:11.640 fin=2022-08-12 11:39:11.756

LocationManagerService seems to support road and rail, and a lot of bluesky stuff

``` SERVICE com.google.android.gms/com.google.android.location.internal.GoogleLocationManagerService b9b4d51 pid=22250 Client: Overridden Flags: dfpg: ar_road_and_rail_transition_enabled = true dfpj: ArRuntimePermission__enable_ar_listener_appop_bugfix = true ArRuntimePermission__enable_ar_transition_appop_bugfix = true dfpm: ArSettings__bypass_ar_pending_intent_temp_allow_list = true disable_force_detection = true enable_activity_recognition_throttling = true enable_app_importance_listener = true sensor_batching_enabled = true dfpv: background_throttle = true flp_wifi_connection_throttle_enabled = true dfqc: BluePixel__flp_enable_blue_pixel = true dfqh: Bluesky__bluesky_tile_version = 5 Bluesky__enable_catching_tflite_illegal_argument_exceptions = true Bluesky__enable_device_ml_chipset = true Bluesky__enable_device_ml_flp = true Bluesky__enable_environment_bearing_for_chipset = true Bluesky__enable_positions_distance_threshold = true Bluesky__lat_lng_kf_bearing_accuracy_rad = 0.58 Bluesky__lat_lng_kf_init_velocity_uncertainty_mps = 2.24 Bluesky__lat_lng_kf_measurement_error_reset_threshold_meters = 101.1 Bluesky__lat_lng_kf_q_sigma_accel_walk_mps2 = 6.94 Bluesky__lat_lng_kf_sigma_vel_threshold_mps = 0.83 Bluesky__lat_lng_kf_speed_accuracy_mps = 1.02 Bluesky__positions_distance_threshold_meters = 65.0 Bluesky__bluesky_use_flp_as_grid_center_and_flp_unc_for_radius = true Bluesky__bluesky_use_gnss_as_grid_center = true Bluesky__device_ml_catch_exception_when_raster_too_small = true Bluesky__bearing_kf_q_sigma_brg_acc_rad_per_sec2 = 0.06 Bluesky__bearing_kf_q_sigma_brg_rate_rad_per_sec = 0.73 Bluesky__bearing_kf_threshold_variance_theta_rad_squared = 29.11 Bluesky__bluesky_allow_stale_or_null_other_location_for_grid_extension = true Bluesky__bluesky_apply_extended_location_staleness_check = true Bluesky__bluesky_chipset_lc_weight = 0.7 Bluesky__bluesky_chipset_lx_weight = 0.57 Bluesky__bluesky_enable_hardware_listener = true Bluesky__bluesky_enable_mdd_geofence = true Bluesky__bluesky_enabled = true dfqu: chre_cc_bug_fix_204899387 = true dfrd: unc2 = true dfqu: chre_cc_bug_fix_204899387 = true dfrg: enable_chre_ar_bluetooth_filtering = true enable_chre_ar_wifi_filtering = true dfrj: ChreGeofence__bug_fix_unload_from_chre_when_nlp_turns_off = true dfrs: wfsna = true dfry: ar_cnn_one_shot_enabled = true ar_gru_burst_confidence_threshold_early_exit_list = 0.95:0.95:0.95:0.95:0.95:0.95 ar_gru_burst_enabled = true ar_road_vehicle_classification_enabled = true dfsx: EalertUx__enable_alert_ux_master = true dftk: FlpAltitude__propose_from_pressure = true FlpAltitude__use_access_point_measurements = true FlpAltitude__accumulate_barometer = true FlpAltitude__enable_time_induced_noise_proposal = true dftg: Flp18__enable_altitude_particle_filter = true Flp18__enable_bluesky_shadow_likelihood = true flp_report_location_on_step_update = true flp_use_particle_fusion = true Flp18__accuracy_factor = 1.7 Flp18__output_linear_kf_process_noise_unknown_pos_m = 2.0 Flp18__output_linear_kf_process_noise_unknown_vel_mps = 0.89 Flp18__output_linear_kf_process_noise_wheels_pos_m = 3.96 Flp18__output_linear_kf_process_noise_wheels_vel_mps = 4.56 Flp18__propose_from_gnss_hysteresis_required_running_suggestions = 2 flp_particle_fusion_resampling_threshold = 0.55 flp_particle_fusion_step_length_factor = 1.2 flp_particle_fusion_step_length_noise_sigma_m = 1.09 flp_particle_fusion_temporal_position_noise_sigma_m = 0.0 Flp18__max_wifi_evidence_age_s = 12.0 flp_particle_fusion_nominal_sigma_scale_gnss = 1.02 flp_particle_fusion_nominal_sigma_scale_wifi = 0.51 Flp18__output_linear_kf_process_noise_feet_pos_m = 2.19 Flp18__output_linear_kf_process_noise_feet_vel_mps = 0.1 Flp18__bluesky_shadows_probability_deweighting_factor = 3.5 dftn: Flp__impersonate_location_history = false dftx: flp_throttle_when_still_interval_ms = 300000 dfua: fop_inertial_anchor_use_stateful_logging = true fop_use_inertial_anchor = true dfug: Geocoder__use_new_geocoder = true dfuv: GeofencerClearCutLogs__enable_clear_cut_logs = true dfuy: GeofencerDumpsys__generate_proto_format_records = true geofencing_log_record_size = 200 geofencing_log_record_ttl = 172800000 GeofencerDumpsys__log_geofencer_internal_events = true GeofencerDumpsys__log_location_and_ar_events = true dfvh: geofence_minimum_alert_interval = 1000 dfvk: Geofencing__request_gps_location_upon_hardware_event = true dfvr: InertialAnchor__use_bugfix_229661067 = true InertialAnchor__use_debug_log_flush_on_stop_bugfix_232418522 = true InertialAnchor__use_system_timestamp_for_pose_on_kitkat = true dfvu: InjectedServices__show_summary_for_location_history = true InjectedServices__show_summary_for_location_sharing = true dfwa: LocationDrivingMode__enable_driving_behavior_bugreport_dump = true enable_driving_behavior_gmscore2 = true LocationDrivingMode__route_setting_dnd_granted_for_driving = true dfwi: location_quality_flp_stats_sampling_rate = 0.1 dfwr: NanoappLogging__nanoapp_logging_enabled = true dfwu: enable_contexthub_api_wrapper = true dfwx: stats_collect_nlp_enabled = 0.01 ueaas = true dc_g = true arcs = true dc_bs = true do_not_package_reset_whitelist = com.google.android.apps.wellbeing ebl = true dfxe: apply_activity_personalization = true dfxh: PlatformUpgradeHandlers__enable_platform_upgrade_detection = true save_platform_version_o = false dfxq: show_scanning_upgrade_notification = true dfxw: SensorCollector__collect_aps_with_locally_administered_mac = true sensor_collection_wifi_scan_delay_ms = 3000 dfyc: sleep_detection_allow_third_party = true sleep_segment_detection_enabled = true enable_multiple_sleep_segments = true log_not_detected_debugging_data = true report_previous_sleep_to_requesting_app_only = true report_segment_or_classify_event_only = true run_alternative_segment_if_none = true dfyf: flp_last_location_max_age_millis = 1200000 ```

Geofencer state is

    Geofencer State:
    Registered geofences:
    Active Geofences:
    Package: gov.colorado.energyoffice.emission, count: 1
        Geofence[CIRCLE id:DYNAMIC_EXIT_GEOFENCE transitions:2 37.391003, -122.086472 100m, resp=5s, dwell=-1ms, @-1] it=2, d=0 IN dwelled gov.colorado.energyoffice.emission
    Package: gov.nrel.cims.openpath, count: 1
        Geofence[CIRCLE id:DYNAMIC_EXIT_GEOFENCE transitions:2 37.391003, -122.086472 100m, resp=5s, dwell=-1ms, @-1] it=2, d=0 IN dwelled gov.nrel.cims.openpath

    Location updater: NearbyGeofenceLocationUpdater.
        Monitoring all now.
        Sentinel geofence: null
    SystemMemoryCache for com.google.android.location.internal.GoogleLocationManagerService
     type = 2
     id = 867daf3e-c03c-4b75-8070-4648f18f6445
     cacheData = [PendingIntentCacheItem [mPendingIntent=PendingIntent{fddbb2e: android.os.BinderProxy@b5e367a}, mExternalKey=81218320-b62c-4d93-a177-05f85a0675f3, mAssociatedGeofenceIds=[DYNAMIC_EXIT_GEOFENCE]], PendingIntentCacheItem [mPendingIntent=PendingIntent{404e6cf: android.os.BinderProxy@ecf22a5}, mExternalKey=a8328ea0-8eec-4628-8333-b573d24f0ed4, mAssociatedGeofenceIds=[DYNAMIC_EXIT_GEOFENCE]]]

    UniqueIds in use: 2
    Last location:
        Time=Fri Aug 12 11:49:37 PDT 2022
        Location[fused 37.391001,-122.086477 hAcc=14 et=+36d1h1m0s717ms alt=-4.799999713897705 vAcc=1 sAcc=??? bAcc=??? {Bundle[mParcelledData.dataSize=880]}]
    Dump of hardware geofencing:
        Class is RealBlockingGeofenceHardware, monitoringType=0, limit=50
        Supported=true, available=false, enabled on this device=true
        Registered geofences:
        <none>
    Location update interval=300s
    Dump of ActivityDetector:
        Interval=180s
    Dump of current state:
        WalkingActivityState
    GeofencerStateMachine:
     total records=212
     rec[0]: time=08-12 11:47:23.161 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_SAVE_ACTIVITY_STATE_CMD
     rec[1]: time=08-12 11:48:04.041 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_SYSTEM_EVENT_CMD
     rec[2]: time=08-12 11:48:43.502 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_SYSTEM_EVENT_CMD
     rec[3]: time=08-12 11:48:55.205 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_LOCATION_CMD
     rec[4]: time=08-12 11:48:56.605 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_LOCATION_CMD
     rec[5]: time=08-12 11:49:17.791 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_LOCATION_CMD
     rec[6]: time=08-12 11:49:17.791 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_LOCATION_AVAILABILITY_CHANGED
     rec[7]: time=08-12 11:49:39.338 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_LOCATION_CMD
     rec[8]: time=08-12 11:50:25.210 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_AR_DEEP_STILL_MODE
     rec[9]: time=08-12 11:50:25.261 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_SAVE_ACTIVITY_STATE_CMD
    curState=WalkingActivityState

and the dumpsys logs

    ### GeofencerDumpsysLogMessage END ###
    GeofencerStatsLogManager:
      Stats elapsed ms: 46651892
      GeofencerDeviceCapabilities:
        gps: supported(true), enabled(true)
        nlp: supported(true), enabled(true)
        significant_motion_detector: supported(true), enabled(false)
        gps_hardware_geofencing: supported(true), enabled(false)
        chre_geofencing: supported(false), enabled(false)
      ProfileInfo:
        isPrimaryUser: true
        isOwnerProfile: true
      Durations:
        STILL_ACTIVITY enabled ms: 41050109
        NO_GEOFENCE enabled ms: 568004
        HAS_GEOFENCE enabled ms: 7
        UNKNOWN_ACTIVITY enabled ms: 2896129
        NOT_INITIALIZED enabled ms: 574
        WALKING_ACTIVITY enabled ms: 1694811
        current(WALKING_ACTIVITY) enabled ms: 442240
        Significant motion detector enabled ms: 33959196
          Currently disabled

Again, it looks like we did have a geofence exit, followed by a change to high accuracy

    enq=2022-08-12 11:39:11.762 disp=2022-08-12 11:39:11.766 fin=2022-08-12 11:39:11.780
  #245: act=local.transition.exited_geofence flg=0x10 pkg=gov.colorado.energyoffice.emission
    +22ms dispatch +116ms finish
    enq=2022-08-12 11:39:11.618 disp=2022-08-12 11:39:11.640 fin=2022-08-12 11:39:11.756
  #246: act=android.location.HIGH_POWER_REQUEST_CHANGE flg=0x10
    0 dispatch +1ms finish
    enq=2022-08-12 11:39:11.701 disp=2022-08-12 11:39:11.701 fin=2022-08-12 11:39:11.702
  #247: act=local.transition.exited_geofence flg=0x10 pkg=gov.nrel.cims.openpath
    +1ms dispatch +65ms finish
    enq=2022-08-12 11:39:11.574 disp=2022-08-12 11:39:11.575 fin=2022-08-12 11:39:11.640
  #248: act=android.net.wifi.SCAN_RESULTS flg=0x4000010 (has extras)
    0 dispatch 0 finish

shankari commented 2 years ago

Again, we see the geofence exit on the pixel phone

  #81: act=local.transition.exited_geofence flg=0x10 pkg=edu.berkeley.eecs.emission
    +41ms dispatch +28ms finish
    enq=2022-08-12 11:40:06.702 disp=2022-08-12 11:40:06.743 fin=2022-08-12 11:40:06.771

and on the personal phone, but even earlier!!

  #245: act=local.transition.exited_geofence flg=0x10 pkg=gov.colorado.energyoffice.emission
    +22ms dispatch +116ms finish
    enq=2022-08-12 11:39:11.618 disp=2022-08-12 11:39:11.640 fin=2022-08-12 11:39:11.756

But we don't have the detailed logs from 11:39 on the personal phone to see why it wasn't recorded properly.

shankari commented 2 years ago

wait, but we do have OpenPATH logs from Sunday, let's see if they have any insights - Looks like we did get two geofence exits, but

68883,1660328661.954,2022-08-12T11:24:21.954000-07:00,GeofenceExitIntentService : onCreate called
68888,1660328662.01,2022-08-12T11:24:22.010000-07:00,"GeofenceExitIntentService : got geofence intent callback with type 2 and location Location[fused 37.390092,-122.083778 hAcc=64 et=+36d0h35m28s359ms alt=-1.899999976158142 vAcc=1 sAcc=??? bAcc=???]"
69228,1660328947.579,2022-08-12T11:29:07.579000-07:00,"TripDiaryStateMachineService : handleAction(local.state.ongoing_trip, local.transition.stopped_moving) called"

69308,1660329551.532,2022-08-12T11:39:11.532000-07:00,GeofenceExitIntentService : onCreate called
69668,1660329834.566,2022-08-12T11:43:54.566000-07:00,"TripDiaryStateMachineService : handleAction(local.state.ongoing_trip, local.transition.stopped_moving) called"

But the location of the geofence exit was the library

shankari commented 2 years ago

Let's try the trip to/from the Indian store today which was completely skipped on both phones.

personal phone

      android.location.PROVIDERS_CHANGED:
        cf3b4d com.google.android.googlequicksearchbox/com.google.android.apps.gsa.broadcastreceiver.external.ExternalCommonBroadcastReceiver
        1dbe555 com.google.android.apps.maps/com.google.android.apps.gmm.locationsharing.usr.LocationAvailabilityChecker$LocationProvidersChangedBroadcastReceiver
        2cfb8c1 com.google.android.gms/.chimera.GmsIntentOperationService$PersistentTrustedReceiver
        42b280c com.google.android.apps.maps/com.google.android.apps.gmm.geofence.GeofenceLocationAvailabilityManager$LocationProviderChangeBroadcastReceiver

      android.location.MODE_CHANGED:
        1dbe555 com.google.android.apps.maps/com.google.android.apps.gmm.locationsharing.usr.LocationAvailabilityChecker$LocationProvidersChangedBroadcastReceiver
        2cfb8c1 com.google.android.gms/.chimera.GmsIntentOperationService$PersistentTrustedReceiver
        42b280c com.google.android.apps.maps/com.google.android.apps.gmm.geofence.GeofenceLocationAvailabilityManager$LocationProviderChangeBroadcastReceiver

      local.transition.exited_geofence:
        1c8218f gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.transitionnotify.TransitionNotificationReceiver
        5d557b8 gov.nrel.cims.openpath/edu.berkeley.eecs.emission.cordova.transitionnotify.TransitionNotificationReceiver
        99228ee gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineReceiver
        ce09991 gov.nrel.cims.openpath/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineReceiver

      com.google.android.apps.gmm.geofence.GeofenceBroadcastReceiver.GEOFENCE_RECEIVER_ACTION:
        b6287a3 com.google.android.apps.maps/com.google.android.apps.gmm.geofence.GeofenceBroadcastReceiver

      com.google.android.googlequicksearchbox.HOME_GEOFENCE:
        a775586 com.google.android.googlequicksearchbox/com.google.android.apps.gsa.staticplugins.opa.ambient.context.trigger.geofence.GeofenceBroadcastReceiver

      com.motorola.mya.semantic.LBS_GEOFENCE_REQUEST:
        14b3be0 com.motorola.moto/com.motorola.mya.semantic.geofence.receiver.LBSGeoFenceTransitionReceiver

Poking deeper into the location services code

    Fused Location Provider:
      source: Request[@30m BALANCED_POWER_ACCURACY, minUpdateDistance=1000.0, WorkSource{10189 com.google.android.gms}]
      listeners:
        10189/com.google.android.gms[.location_base]/fdf3309c (FINE) Request[PASSIVE, minUpdateInterval=0s, maxCachedUpdateAge=0s, THROTTLE_ALWAYS, WorkSource{10189 com.google.android.gms}]
        10189/com.google.android.gms[.location_base]/3a157252 (FINE) Request[@30m BALANCED_POWER_ACCURACY, minUpdateInterval=5m, minUpdateDistance=1000.0, THROTTLE_NEVER, WorkSource{10189 com.google.android.gms}]
      last availability: LocationAvailability[true]
      last location (fine): Location[fused 37.374582,-122.055575 hAcc=21 et=+40d7h1m9s740ms alt=10.09999942779541 vAcc=1 sAcc=??? bAcc=??? {Bundle[{noGPSLocation=Location[fused 37.374582,-122.055575 hAcc=21 et=+40d7h1m9s740ms alt=10.09999942779541 vAcc=1 sAcc=??? bAcc=??? {Bundle[{locationSubtype=5, networkLocationType=wifi, floorLabel=1, wifiScan=[2, -20, -11, 127, -49, 0, 0, 0, 0, 22, -90, 50, -106, -36, -120, -56, -118, -3, 0, 0, 0, 0, 0, 0, 0, 0, 117, 5, 19, 124, -109, 28, -77, -117, -4, 0, 0, 0, 0, 0, 0, 0, 0, 26, -99, -40, -32, -113, 92, -78, -122, 0, 0, 0, 0, 0, 0, 0, 0, 0, -112, -5, 119, 126, 104, -96, -90, -122, 0, 0, 0, 0, 0, 0, 0, 0, 0], indoorProbability=0.753582, levelId=0x808fb6ef32e2ed73:0x97a9209c3010cd84, nlpVersion=2023, verticalAccuracy=1.3674412}]}]}]}]
      last location (coarse): Location[fused 37.387387,-122.047926 hAcc=2000 et=+40d6h54m32s265ms vAcc=0 sAcc=??? bAcc=???]

last fine location is in Sunnyvale near the Indian store	last coarse location is also in Sunnyvale but north of Central

Last location is from the network and is at the India store.

    Location Engine:
      --FusionEngine--
        enabled: true
        controllers:
          GpsBatch[requested=false, enabled=true, start(ERT)=3478345503ms, clients=[], interval=0ms, trigger=false, minpulse=MAX, NoBatching]
          Passive[requested=true, enabled=true, start(ERT)=3414848874ms, clients=[]]
          StepDetector[requested=false, enabled=true, clients=[]]
          Nlp[requested=true, enabled=true, start(ERT)=3480886385ms, clients=[10189:com.google.android.gms], interval=1800000ms, trigger=false, maxWaitTime=1800000, debug info=true]
          NlpLowPower[requested=false, enabled=true, clients=[], interval=MAX, trigger=false, maxWaitTime=0, debug info=false]
          ActivityRecognition[requested=false, enabled=true, start(ERT)=3478345508ms, clients=[], interval=30000ms, trigger=false, maxWaitTime=0, debug info=false]
          Bluesky[requested=false, enabled=true, clients=[]]
          PressureProvider[requested=true, enabled=true, start(ERT)=3480886396ms, clients=[10189:com.google.android.gms]]
        last locations:
          fused: Location[fused 37.374582,-122.055575 hAcc=21 et=+40d7h1m9s740ms alt=10.09999942779541 vAcc=1 sAcc=??? bAcc=??? {Bundle[{floorLabel=1, wifiScan=[69, 79, -1, -1, -112, 0, 0, 0, 1, 0, 8, 0, -20, -11, 127, -49, 0, 0, 0, 0, 2, 0, -1, -1, 36, 0, 0, 0, 4, 0, 0, 0, 22, -90, 50, -106, -36, -120, -56, -1, 117, 5, 19, 124, -109, 28, -77, -1, 26, -99, -40, -32, -113, 92, -78, -1, -112, -5, 119, 126, 104, -96, -90, -1, 3, 0, -1, -1, 20, 0, 0, 0, 4, 0, 0, 0, -103, 9, 0, 0, -98, 9, 0, 0, -123, 9, 0, 0, -123, 9, 0, 0, 4, 0, -1, -1, 4, 0, 0, 0, 0, 0, 0, 0, 5, 0, -1, -1, 4, 0, 0, 0, 0, 0, 0, 0, 6, 0, -1, -1, 4, 0, 0, 0, 0, 0, 0, 0, 7, 0, -1, -1, 4, 0, 0, 0, 0, 0, 0, 0, 8, 0, -1, -1, 4, 0, 0, 0, 0, 0, 0, 0], indoorProbability=0.753582, noGPSLocation=Location[fused 37.374582,-122.055575 hAcc=21 et=+40d7h1m9s740ms alt=10.09999942779541 vAcc=1 sAcc=??? bAcc=??? {Bundle[{locationSubtype=5, networkLocationType=wifi, floorLabel=1, wifiScan=[2, -20, -11, 127, -49, 0, 0, 0, 0, 22, -90, 50, -106, -36, -120, -56, -118, -3, 0, 0, 0, 0, 0, 0, 0, 0, 117, 5, 19, 124, -109, 28, -77, -117, -4, 0, 0, 0, 0, 0, 0, 0, 0, 26, -99, -40, -32, -113, 92, -78, -122, 0, 0, 0, 0, 0, 0, 0, 0, 0, -112, -5, 119, 126, 104, -96, -90, -122, 0, 0, 0, 0, 0, 0, 0, 0, 0], indoorProbability=0.753582, levelId=0x808fb6ef32e2ed73:0x97a9209c3010cd84, nlpVersion=2023, verticalAccuracy=1.3674412}]}], locationType=3, levelId=0x808fb6ef32e2ed73:0x97a9209c3010cd84}]}]
          gps: null
          network: Location[network 37.374582,-122.055575 hAcc=21 et=+40d7h1m9s740ms alt=10.09999942779541 vAcc=1 sAcc=??? bAcc=??? {Bundle[{wifiScan=[69, 79, -1, -1, -112, 0, 0, 0, 1, 0, 8, 0, -20, -11, 127, -49, 0, 0, 0, 0, 2, 0, -1, -1, 36, 0, 0, 0, 4, 0, 0, 0, 22, -90, 50, -106, -36, -120, -56, -1, 117, 5, 19, 124, -109, 28, -77, -1, 26, -99, -40, -32, -113, 92, -78, -1, -112, -5, 119, 126, 104, -96, -90, -1, 3, 0, -1, -1, 20, 0, 0, 0, 4, 0, 0, 0, -103, 9, 0, 0, -98, 9, 0, 0, -123, 9, 0, 0, -123, 9, 0, 0, 4, 0, -1, -1, 4, 0, 0, 0, 0, 0, 0, 0, 5, 0, -1, -1, 4, 0, 0, 0, 0, 0, 0, 0, 6, 0, -1, -1, 4, 0, 0, 0, 0, 0, 0, 0, 7, 0, -1, -1, 4, 0, 0, 0, 0, 0, 0, 0, 8, 0, -1, -1, 4, 0, 0, 0, 0, 0, 0, 0], locationType=3, levelId=0x808fb6ef32e2ed73:0x97a9209c3010cd84}]}]

The closest activity was IN_VEHICLE (since we had just finished the car trip). There is also a pedestrian switching fusion (whatever that means)!!

      --SensorFusion--
      FLP orientation source: InertialAnchor
      InjectionSensorFusion: time(ns): {lastAbsoluteTimeNs=3481269740000000,lastInjectedTimeNs=0}
      ParticleFilterFusion: should run: false
        Particle filter implementation not instantiated.
      FailOverFusion:activity{time(ns)=3481009359000000, activity=IN_VEHICLE} time(ns): {primary=3481269740000000,provider=WIFI, failover=0} primary location is used
      PedestrianSwitchingFusion: activity{time(ns)=3481009359000000, activity=false} pedestrianFusion:false
      FailOverFusion:activity{time(ns)=3481009359000000, activity=IN_VEHICLE} time(ns): {primary=0, failover=3481269740000000,provider=WIFI} failover location is used
      FilteringFusion based on WIFI position.
      ElevationGraphOptimizationSensorFusion - dump - 3481286399000000

The location services log is not super interesting, we apparently kept getting WiFi location throughout the trips and giving to to Google Play Services.

The Geofence locations are correct and are set to my house.

    Geofencer State:
    Registered geofences:
    Active Geofences:
    Package: gov.colorado.energyoffice.emission, count: 1
        Geofence[CIRCLE id:DYNAMIC_EXIT_GEOFENCE transitions:2 [home] 100m, resp=5s, dwell=-1ms, @-1] it=2, d=6 IN dwelled gov.colorado.energyoffice.emission
    Package: gov.nrel.cims.openpath, count: 1
        Geofence[CIRCLE id:DYNAMIC_EXIT_GEOFENCE transitions:2 [home] 100m, resp=5s, dwell=-1ms, @-1] it=2, d=8 IN dwelled gov.nrel.cims.openpath

    UniqueIds in use: 2
    Last location:
        Time=Tue Aug 16 17:32:44 PDT 2022
        Location[fused [home] hAcc=93 et=+40d6h44m5s100ms alt=-4.799999713897705 vAcc=13 sAcc=??? bAcc=??? {Bundle[mParcelledData.dataSize=764]}]
    Dump of hardware geofencing:
        Class is RealBlockingGeofenceHardware, monitoringType=0, limit=50
        Supported=true, available=false, enabled on this device=true
        Registered geofences:
            id=0 Geofence[CIRCLE id:DYNAMIC_EXIT_GEOFENCE transitions:2 [home] 100m, resp=5s, dwell=-1ms, @-1] it=2, d=8 IN dwelled gov.nrel.cims.openpath
            id=1 Geofence[CIRCLE id:DYNAMIC_EXIT_GEOFENCE transitions:2 [home] 100m, resp=5s, dwell=-1ms, @-1] it=2, d=6 IN dwelled gov.colorado.energyoffice.emission
    Location update interval=-1s
    Dump of ActivityDetector:
        Interval=300s
    Dump of current state:
        FastMovingActivityState
        Using hardware geofencing=HARDWARE_GEOFENCE_STATE_IN_USE

However, note that, in comparison to the previous state, the state is FastMovingActivityState and there are only SM_SYSTEM_EVENT_CMD events, no SM_LOCATION_AVAILABILITY_CHANGED or SM_LOCATION_CMD

    GeofencerStateMachine:
     total records=163
     rec[0]: time=08-16 17:43:29.183 processed=FastMovingActivityState org=FastMovingActivityState dest=<null> what=SM_SAVE_ACTIVITY_STATE_CMD
     rec[1]: time=08-16 17:43:39.178 processed=FastMovingActivityState org=FastMovingActivityState dest=<null> what=SM_SYSTEM_EVENT_CMD
     rec[2]: time=08-16 17:44:05.425 processed=FastMovingActivityState org=FastMovingActivityState dest=<null> what=SM_SYSTEM_EVENT_CMD
     rec[3]: time=08-16 17:44:05.924 processed=FastMovingActivityState org=FastMovingActivityState dest=<null> what=SM_SYSTEM_EVENT_CMD
     rec[4]: time=08-16 17:44:19.520 processed=FastMovingActivityState org=FastMovingActivityState dest=<null> what=SM_SYSTEM_EVENT_CMD
     rec[5]: time=08-16 17:45:39.239 processed=FastMovingActivityState org=FastMovingActivityState dest=<null> what=SM_SAVE_ACTIVITY_STATE_CMD
     rec[6]: time=08-16 17:47:49.090 processed=FastMovingActivityState org=FastMovingActivityState dest=<null> what=SM_SYSTEM_EVENT_CMD
     rec[7]: time=08-16 17:48:01.900 processed=FastMovingActivityState org=FastMovingActivityState dest=<null> what=SM_SYSTEM_EVENT_CMD
     rec[8]: time=08-16 17:49:54.124 processed=FastMovingActivityState org=FastMovingActivityState dest=<null> what=SM_SYSTEM_EVENT_CMD
     rec[9]: time=08-16 17:50:04.760 processed=FastMovingActivityState org=FastMovingActivityState dest=<null> what=SM_SYSTEM_EVENT_CMD
    curState=FastMovingActivityState
    LogRecords: capacity=200

and in the dumpsys, we have the below.

    GeofencerStatsLogManager:
      Stats elapsed ms: 66437670
      GeofencerDeviceCapabilities:
        gps: supported(true), enabled(true)
        nlp: supported(true), enabled(true)
        significant_motion_detector: supported(true), enabled(false)
        gps_hardware_geofencing: supported(true), enabled(true)
        chre_geofencing: supported(false), enabled(false)
      ProfileInfo:
        isPrimaryUser: true
        isOwnerProfile: true
      Durations:
        UNAVAILABLE_ACTIVITY enabled ms: 1145374
        STILL_ACTIVITY enabled ms: 60332361
        FAST_MOVING_ACTIVITY enabled ms: 1762580
        HAS_GEOFENCE enabled ms: 1
        NOT_INITIALIZED enabled ms: 406
        UNKNOWN_ACTIVITY enabled ms: 910269
        WALKING_ACTIVITY enabled ms: 1285035
        current(FAST_MOVING_ACTIVITY) enabled ms: 1001624
        Significant motion detector enabled ms: 23830163
          Currently disabled

Note that now, the supported and enabled flags are different from Friday.

Now

        significant_motion_detector: supported(true), enabled(false)
        gps_hardware_geofencing: supported(true), enabled(true)

Friday

        significant_motion_detector: supported(true), enabled(false)
        gps_hardware_geofencing: supported(true), enabled(false)

We need some reverse engineering of the geofence code to better understand this. Unfortunately the Google Play Services code is not open source. We could also choose to drop them and just write our own Geofencer...

shankari commented 2 years ago

Double checking that we are looking at the logs from the same phone

And there is a difference.

shankari commented 2 years ago

FYI, there is a flutter plugin with a re-implementation of the geofence API that we can use as a baseline if we want to reimplement. https://morioh.com/p/5b22f855bb34

I cannot find any other information on GeofencerStatsLogManager or GeofencerDeviceCapabilities.

shankari commented 2 years ago

Of the sensors listed above, the significant motion sensor is in fact user accessible. https://developer.android.com/guide/topics/sensors/sensors_motion#sensors-motion-significant

Will just enabling it fix everything? Still not sure what GPS hardware geofencing is, except for https://source.android.com/reference/hal/struct_gps_geofencing_interface but it is not clear what enables/disables it

Let's briefly check the pixel to see if the behavior is consistent.

    #7: PendingIntentRecord{ade6ae9 com.google.android.gms/geofencer_provider startService}
      uid=10190 packageName=com.google.android.gms featureId=geofencer_provider type=startService flags=0x2000000
      requestIntent=act=com.google.android.location.internal.action.GEOFENCER_LOCATION_RESULT pkg=com.google.android.gms cmp=com.google.android.gms/com.google.android.location.internal.PendingIntentCallbackService

    #28: PendingIntentRecord{373c246 com.google.android.gms/com.google.android.gms.location_base broadcastIntent}
      uid=10190 packageName=com.google.android.gms featureId=com.google.android.gms.location_base type=broadcastIntent flags=0x4000000
      requestIntent=act=com.google.android.location.ALARM_WAKEUP_VEHICLE_EXIT_DETECTOR

        geofencer_provider=[
          Access: [top-s] 2022-05-06 23:30:13.134 (-101d18h14m39s434ms)
          Access: [fgsvc-s] 2022-05-07 00:22:52.527 (-101d17h22m0s41ms)
          Access: [fg-s] 2022-05-07 01:36:30.351 (-101d16h8m22s217ms)
        ]

Here's some ContextHubClient which is apparently used by a lot of our favorite program and something called carcrash.

[ContextHubClient endpointID: 35, contextHub: 0, attributionTag: activity_recognition_provider, package: com.google.android.gms messageChannelNanoappSet: (0x476f6f676c00100b auth state: GRANTED)]
[ContextHubClient endpointID: 36, contextHub: 0, attributionTag: fused_location_provider, package: com.google.android.gms messageChannelNanoappSet: (0x476f6f676c001013 auth state: GRANTED)]
[ContextHubClient endpointID: 38, contextHub: 0, attributionTag: geofencer_provider, package: com.google.android.gms messageChannelNanoappSet: (0x476f6f676c001004 auth state: GRANTED)]
[ContextHubClient endpointID: 39, contextHub: 0, attributionTag: carcrash, package: com.google.android.gms messageChannelNanoappSet: (0x476f6f676c00100d auth state: GRANTED)]

Details of the location service

  Location Providers:
    passive provider:
      last location=Location[gps (global rug) hAcc=12.905596 et=+4d10h26m54s588ms alt=-5.636474609375 vAcc=6.8031898 vel=16.12 sAcc=1.755591 bear=121.4 bAcc=2.0050397 {Bundle[{satellites=15, maxCn0=32, meanCn0=22}]}]
    network provider:
      service: ProviderRequest[@+6h0m0s0ms, LOW_POWER, WorkSource{10150 com.google.android.as}]
      last location=Location[network eagle park hAcc=96.229 et=+4d10h24m30s680ms alt=-3.1999998092651367 vAcc=4.3728175 {Bundle[mParcelledData.dataSize=68]}]
    fused provider:
      service: ProviderRequest[OFF]
      last location=Location[fused global rug hAcc=13.062 et=+4d10h26m54s588ms alt=-5.636474609375 vAcc=6.8031898 vel=16.079884 sAcc=1.755591 bear=120.9847 bAcc=2.0050397]
    gps provider:
      service: ProviderRequest[OFF]
      last location=Location[gps 37.386182,-122.084879 hAcc=12.905596 et=+4d10h26m54s588ms alt=-5.636474609375 vAcc=6.8031898 vel=16.12 sAcc=1.755591 bear=121.4 bAcc=2.0050397 {Bundle[{satellites=15, maxCn0=32, meanCn0=22}]}]

Unlike on my personal phone, it looks like locations are from GPS, maybe because there is no SIM card.

    08-16 17:34:13.224: gps provider received location[1]
    08-16 17:34:13.237: fused provider received location[1]
    08-16 17:34:14.225: gps provider received location[1]
    08-16 17:34:14.239: fused provider received location[1]

Here are the related notifications again

      android.location.PROVIDERS_CHANGED:
        c283f03 com.google.android.gms/.chimera.GmsIntentOperationService$PersistentTrustedReceiver
        93cc901 com.google.android.googlequicksearchbox/com.google.android.apps.gsa.broadcastreceiver.external.ExternalCommonBroadcastReceiver
        118a558 com.google.android.apps.maps/com.google.android.apps.gmm.geofence.GeofenceLocationAvailabilityManager$LocationProviderChangeBroadcastReceiver
        ea23410 com.google.android.apps.chromecast.app/.gf.maintenance.GeofenceSystemChangeBroadcastReceiver
        a7c61c9 com.google.android.apps.maps/com.google.android.apps.gmm.locationsharing.usr.LocationAvailabilityChecker$LocationProvidersChangedBroadcastReceiver
      android.location.MODE_CHANGED:
        c283f03 com.google.android.gms/.chimera.GmsIntentOperationService$PersistentTrustedReceiver
        118a558 com.google.android.apps.maps/com.google.android.apps.gmm.geofence.GeofenceLocationAvailabilityManager$LocationProviderChangeBroadcastReceiver
        6375413 com.google.android.apps.work.clouddpc/.receivers.LocationModeChangedReceiver
        a7c61c9 com.google.android.apps.maps/com.google.android.apps.gmm.locationsharing.usr.LocationAvailabilityChecker$LocationProvidersChangedBroadcastReceiver

wrt location settings

      source: Request[@5m BALANCED_POWER_ACCURACY, WorkSource{10268 gov.colorado.energyoffice.emission, 10281 com.fabmoqc.mamobilite, 10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}]
      listeners:
        10190/com.google.android.gms[fused_provider_shim]/b08d3bb2 (FINE) Request[PASSIVE, maxCachedUpdateAge=0s, THROTTLE_NEVER, WorkSource{10190 com.google.android.gms}]
        10190/com.google.android.gms[awareness_provider]/5416ca16 (FINE) Request[PASSIVE, minUpdateInterval=0s, maxCachedUpdateAge=0s, THROTTLE_ALWAYS, WorkSource{10190 com.google.android.gms}]
        10190/com.google.android.gms[geofencer_provider]/bd92c5d4 (FINE) Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10268 gov.colorado.energyoffice.emission, 10281 com.fabmoqc.mamobilite, 10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}]
      last availability: LocationAvailability[false]
      last location (fine): Location[fused (globalrug) hAcc=13.062 et=+4d10h26m54s588ms alt=-5.636474609375 vAcc=6.8031898 vel=16.079884 sAcc=1.755591 bear=120.9847 bAcc=2.0050397 {Bundle[{}]}]
      last location (coarse): Location[fused (between elmonte and miramonte) hAcc=2000.0 et=+4d10h21m35s298ms]

        last locations:
          fused: Location[fused (global rug) hAcc=13.062 et=+4d10h26m54s588ms alt=-5.636474609375 vAcc=6.8031898 vel=16.079884 sAcc=1.755591 bear=120.9847 bAcc=2.0050397 {Bundle[{locationType=1}]}]
          gps: Location[gps (global rug) hAcc=12.905596 et=+4d10h26m54s588ms alt=-5.636474609375 vAcc=6.8031898 vel=16.12 sAcc=1.755591 bear=121.4 bAcc=2.0050397 {Bundle[mParcelledData.dataSize=96]}]
          network: Location[network (eagle park) hAcc=96.229 et=+4d10h24m30s680ms alt=-3.1999998092651367 vAcc=4.3728175 {Bundle[{wifiScan=[69, 79, -1, -1, -112, 0, 0, 0, 1, 0, 8, 0, -40, 49, -43, 22, 0, 0, 0, 0, 2, 0, -1, -1, 36, 0, 0, 0, 4, 0, 0, 0, -72, 44, 23, -29, 32, 52, -82, -1, -106, -22, 28, -92, 81, -4, -86, -1, 64, 109, 49, -120, -128, 40, -91, -1, 3, -119, 94, 121, -120, 28, -93, -1, 3, 0, -1, -1, 20, 0, 0, 0, 4, 0, 0, 0, 108, 9, 0, 0, -98, 9, 0, 0, -118, 9, 0, 0, -123, 9, 0, 0, 4, 0, -1, -1, 4, 0, 0, 0, 0, 0, 0, 0, 5, 0, -1, -1, 4, 0, 0, 0, 0, 0, 0, 0, 6, 0, -1, -1, 4, 0, 0, 0, 0, 0, 0, 0, 7, 0, -1, -1, 4, 0, 0, 0, 0, 0, 0, 0, 8, 0, -1, -1, 4, 0, 0, 0, 0, 0, 0, 0], locationType=3}]}]

looking at the logs, there's a bunch of geofencer provider logs around 7am, then just a couple of times until 17:21, just before we left. And then a bunch of locations delivered to the awareness manager

      08-16 07:48:07.192: -client 10190/com.google.android.gms[geofencer_provider]/bd92c5d4

      08-16 13:48:40.521: -client 10190/com.google.android.gms[geofencer_provider]/bd92c5d4

      08-16 17:30:31.884: -client 10190/com.google.android.gms[geofencer_provider]/bd92c5d4
      08-16 17:31:14.381: -client 10190/com.google.android.gms[geofencer_provider]/bd92c5d4
      08-16 17:33:25.891: -client 10190/com.google.android.gms[geofencer_provider]/bd92c5d4
      08-16 17:33:27.174: -client 10190/com.google.android.gms[geofencer_provider]/bd92c5d4

      08-16 17:33:36.067: engine request = Request[OFF]
      08-16 17:35:19.293: delivered location[1] to 10190/com.google.android.gms[awareness_provider]/5416ca16
      08-16 17:35:20.291: received GPS location[1]
      08-16 17:35:20.292: delivered location[1] to 10190/com.google.android.gms[fused_provider_shim]/b08d3bb2
      08-16 17:35:20.293: delivered location[1] to 10190/com.google.android.gms[awareness_provider]/5416ca16
      08-16 17:35:21.285: received GPS location[1]
...
      08-16 17:38:34.359: received LocationAvailability[true]
      08-16 17:44:52.976: +client 10190/com.google.android.gms[geofencer_provider]/bd92c5d4 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10268 gov.colorado.energyoffice.emission, 10281 com.fabmoqc.mamobilite, 10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}]
      08-16 17:44:52.980: engine request = Request[@5m BALANCED_POWER_ACCURACY, WorkSource{10268 gov.colorado.energyoffice.emission, 10281 com.fabmoqc.mamobilite, 10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}]
      08-16 17:44:52.985: received LocationAvailability[false]
      08-16 17:44:53.000: received LocationAvailability[false]

And the geofence logs again have FastMovingActivityState but it looks like we took the logs only after we actually started walking.

    Location updater: NearbyGeofenceLocationUpdater.
        Monitoring all now.
        Sentinel geofence: null
    SystemMemoryCache for com.google.android.location.internal.GoogleLocationManagerService
     type = 2
     id = 164c2c8a-58e8-4e50-9051-190698ff4f9c
     cacheData = [PendingIntentCacheItem [mPendingIntent=PendingIntent{6b8bf20: android.os.BinderProxy@3028598}, mExternalKey=acb88129-7c41-4fb7-8aef-4631077502c3, mAssociatedGeofenceIds=[DYNAMIC_EXIT_GEOFENCE]], PendingIntentCacheItem [mPendingIntent=PendingIntent{9a550d9: android.os.BinderProxy@7f0e37b}, mExternalKey=bcef4a45-8f3b-4ab7-a85f-8f0137cc5cb1, mAssociatedGeofenceIds=[DYNAMIC_EXIT_GEOFENCE]], PendingIntentCacheItem [mPendingIntent=PendingIntent{adbba9e: android.os.BinderProxy@85761f1}, mExternalKey=faf33ba6-6079-44f9-aa09-849a2d139e41, mAssociatedGeofenceIds=[DYNAMIC_EXIT_GEOFENCE]], PendingIntentCacheItem [mPendingIntent=PendingIntent{69ec97f: android.os.BinderProxy@e7251d6}, mExternalKey=6cd52563-2c73-4c37-a7bd-af9ed67a313b, mAssociatedGeofenceIds=[DYNAMIC_EXIT_GEOFENCE]]]

    UniqueIds in use: 4
    Last location:
        Time=Tue Aug 16 17:33:27 PDT 2022
        Location[fused 37.389619,-122.086562 hAcc=86.914 et=+4d10h24m30s680ms alt=-3.1999998092651367 vAcc=4.8283854 vel=0.34380245 bear=221.99493 {Bundle[mParcelledData.dataSize=276]}]
    Dump of hardware geofencing:
        Class is RealBlockingGeofenceHardware, monitoringType=0, limit=50
        Supported=true, available=false, enabled on this device=true
        Registered geofences:
        <none>
    Location update interval=300s
    Dump of ActivityDetector:
        Interval=180s
    Dump of current state:
        WalkingActivityState
    GeofencerStateMachine:
     total records=316
     rec[0]: time=08-16 17:43:11.507 processed=FastMovingActivityState org=FastMovingActivityState dest=<null> what=SM_SAVE_ACTIVITY_STATE_CMD
     rec[1]: time=08-16 17:43:18.331 processed=FastMovingActivityState org=FastMovingActivityState dest=<null> what=SM_SYSTEM_EVENT_CMD
     rec[2]: time=08-16 17:44:05.094 processed=FastMovingActivityState org=FastMovingActivityState dest=<null> what=SM_SYSTEM_EVENT_CMD
     rec[3]: time=08-16 17:44:19.125 processed=FastMovingActivityState org=FastMovingActivityState dest=<null> what=SM_SAVE_ACTIVITY_STATE_CMD
     rec[4]: time=08-16 17:44:52.951 processed=FastMovingActivityState org=FastMovingActivityState dest=<null> what=SM_SAVE_ACTIVITY_STATE_CMD
     rec[5]: time=08-16 17:44:52.953 processed=FastMovingActivityState org=FastMovingActivityState dest=WalkingActivityState what=SM_ACTIVITY_CMD
     rec[6]: time=08-16 17:44:52.976 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_UPDATE_DETECTOR_REQUIREMENT_CMD
     rec[7]: time=08-16 17:44:52.994 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_LOCATION_AVAILABILITY_CHANGED
     rec[8]: time=08-16 17:44:53.004 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_LOCATION_AVAILABILITY_CHANGED
     rec[9]: time=08-16 17:44:53.020 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_SAVE_ACTIVITY_STATE_CMD
    curState=WalkingActivityState
    LogRecords: capacity=200

Since this is a pixel running android 12, it does support CHRE.

    GeofencerStatsLogManager:
      Stats elapsed ms: 119910801
      GeofencerDeviceCapabilities:
        gps: supported(true), enabled(true)
        nlp: supported(true), enabled(true)
        significant_motion_detector: supported(true), enabled(false)
        gps_hardware_geofencing: supported(true), enabled(false)
        chre_geofencing: supported(true), enabled(false)
      ProfileInfo:
        isPrimaryUser: true
        isOwnerProfile: true
      Durations:
        FAST_MOVING_ACTIVITY enabled ms: 676937
        STILL_ACTIVITY enabled ms: 42975
        UNAVAILABLE_ACTIVITY enabled ms: 32628859
        WALKING_ACTIVITY enabled ms: 141658
        current(WALKING_ACTIVITY) enabled ms: 20373
        Significant motion detector enabled ms: 32636794
          Currently disabled
      Counters:
        locationRequests: 8
        locationReceived: 16
        sentinelFenceUpdatesNonChre: 0
        sentinelFenceUpdatesChre: 0
        geofenceCountMaximum: 0
      Events happened: 46
      Events sampled: 0

    Dump of CHRE hardware geofencing:
        Class is BlockingChreGeofenceHardware, limit=-1
        Enabled on this device=false
        Registered geofences:
        <none>
    Current list of nanoapp logging IDs  476f6f676c001004
    Have active CHRE settings listener
    Has active CHRE connection status listener : false. Connected : false

    ContextHub State:
      NanoApps by ID:
        AppId=0x476f6f676c001004, UID=-1, Version=262163'
        AppId=0x476f6f676c00100b, UID=-1, Version=196620'
        AppId=0x476f6f676c00100d, UID=-1, Version=18'
        AppId=0x476f6f676c001012, UID=-1, Version=9'
        AppId=0x476f6f676c001013, UID=-1, Version=196617'
      NanoApps by UID:

the activity transition stats are not very useful

    ####ActivityTransitionListeners Stats Start
    Overall work source=WorkSource{}
    Clients:
      Duration: 9:56:52, Package: com.google.android.apps.scone, Tag: null, WorkSource: WorkSource{}
      Duration: 33:11:48, Package: com.google.android.googlequicksearchbox, Tag: null, WorkSource: WorkSource{}
    ####ActivityTransitionListeners Stats End

but these logs (unclear what is generating them) make a strong case for the activity transition working properly

    08-16 17:35:23.290 @383186701 GPS_LOCATION RealLocation [location=Location[gps (el camino and shoreline) hAcc=10.077073 et=+4d10h26m26s605ms alt=-2.889862060546875 vAcc=3.2988749 vel=5.51 sAcc=1.2812884 bear=184.0 bAcc=7.4860463 {Bundle[{satellites=13, maxCn0=30, meanCn0=24}]}] satellites=13 bearing=184.0 altitude=-2.889862060546875]
...
    08-16 17:35:51.227 @383214638 GPS_LOCATION RealLocation [location=Location[gps (global rug) hAcc=12.905596 et=+4d10h26m54s588ms alt=-5.636474609375 vAcc=6.8031898 vel=16.12 sAcc=1.755591 bear=121.4 bAcc=2.0050397 {Bundle[{satellites=15, maxCn0=32, meanCn0=22}]}] satellites=15 bearing=121.4 altitude=-5.636474609375]

    08-16 17:35:51.279 @383214690 CHRE_AR_RESULT reason=3, sampleCount=9, transitionCount=0
    08-16 17:35:51.291 @383214702 ACTIVITY_DETECTION_RESULT ActivityRecognitionResult [probableActivities=[DetectedActivity [type=IN_VEHICLE, confidence=96], DetectedActivity [type=IN_ROAD_VEHICLE, confidence=96], DetectedActivity [type=IN_RAIL_VEHICLE, confidence=3], DetectedActivity [type=ON_BICYCLE, confidence=0], DetectedActivity [type=WALKING, confidence=0]], timeMillis=1660696551290, elapsedRealtimeMillis=383214701] sentToClient=true

    08-16 17:36:26.521 @383249932 CHRE_AR_RESULT reason=3, sampleCount=11, transitionCount=0
    08-16 17:36:26.528 @383249939 ACTIVITY_DETECTION_RESULT ActivityRecognitionResult [probableActivities=[DetectedActivity [type=IN_VEHICLE, confidence=97], DetectedActivity [type=IN_ROAD_VEHICLE, confidence=97], DetectedActivity [type=IN_RAIL_VEHICLE, confidence=2], DetectedActivity [type=UNKNOWN, confidence=0], DetectedActivity [type=WALKING, confidence=0]], timeMillis=1660696586527, elapsedRealtimeMillis=383249938] sentToClient=true

    08-16 17:43:11.455 @383654866 CHRE_AR_RESULT reason=3, sampleCount=10, transitionCount=0
    08-16 17:43:11.471 @383654882 ACTIVITY_DETECTION_RESULT ActivityRecognitionResult [probableActivities=[DetectedActivity [type=UNKNOWN, confidence=41], DetectedActivity [type=IN_VEHICLE, confidence=10], DetectedActivity [type=ON_BICYCLE, confidence=10], DetectedActivity [type=ON_FOOT, confidence=10], DetectedActivity [type=STILL, confidence=10], DetectedActivity [type=WALKING, confidence=10], DetectedActivity [type=RUNNING, confidence=10], DetectedActivity [type=IN_ROAD_VEHICLE, confidence=10], DetectedActivity [type=IN_RAIL_VEHICLE, confidence=10]], timeMillis=1660696991470, elapsedRealtimeMillis=383654881] sentToClient=true
    08-16 17:43:11.507 @383654918 ALARM_RESET_WINDOW 8 383684918 3750

    08-16 17:43:45.286 @383688697 CHRE_AR_RESULT reason=3, sampleCount=11, transitionCount=0
    08-16 17:43:45.293 @383688704 ACTIVITY_DETECTION_RESULT ActivityRecognitionResult [probableActivities=[DetectedActivity [type=UNKNOWN, confidence=41], DetectedActivity [type=IN_VEHICLE, confidence=10], DetectedActivity [type=ON_BICYCLE, confidence=10], DetectedActivity [type=ON_FOOT, confidence=10], DetectedActivity [type=STILL, confidence=10], DetectedActivity [type=WALKING, confidence=10], DetectedActivity [type=RUNNING, confidence=10], DetectedActivity [type=IN_ROAD_VEHICLE, confidence=10], DetectedActivity [type=IN_RAIL_VEHICLE, confidence=10]], timeMillis=1660697025293, elapsedRealtimeMillis=383688704] sentToClient=true
    08-16 17:43:45.319 @383688730 ALARM_RESET_WINDOW 8 383718729 3750

    08-16 17:44:19.084 @383722495 CHRE_AR_RESULT reason=3, sampleCount=3, transitionCount=0
    08-16 17:44:19.093 @383722504 ACTIVITY_DETECTION_RESULT ActivityRecognitionResult [probableActivities=[DetectedActivity [type=UNKNOWN, confidence=41], DetectedActivity [type=IN_VEHICLE, confidence=10], DetectedActivity [type=ON_BICYCLE, confidence=10], DetectedActivity [type=ON_FOOT, confidence=10], DetectedActivity [type=STILL, confidence=10], DetectedActivity [type=WALKING, confidence=10], DetectedActivity [type=RUNNING, confidence=10], DetectedActivity [type=IN_ROAD_VEHICLE, confidence=10], DetectedActivity [type=IN_RAIL_VEHICLE, confidence=10]], timeMillis=1660697059093, elapsedRealtimeMillis=383722504] sentToClient=true

    08-16 17:44:52.897 @383756308 CHRE_AR_RESULT reason=3, sampleCount=5, transitionCount=0
    08-16 17:44:52.906 @383756317 ACTIVITY_DETECTION_RESULT ActivityRecognitionResult [probableActivities=[DetectedActivity [type=ON_FOOT, confidence=76], DetectedActivity [type=WALKING, confidence=76], DetectedActivity [type=IN_VEHICLE, confidence=10], DetectedActivity [type=IN_RAIL_VEHICLE, confidence=10], DetectedActivity [type=ON_BICYCLE, confidence=6], DetectedActivity [type=IN_ROAD_VEHICLE, confidence=6], DetectedActivity [type=UNKNOWN, confidence=1], DetectedActivity [type=RUNNING, confidence=1]], timeMillis=1660697092905, elapsedRealtimeMillis=383756316] sentToClient=true

    08-16 17:44:52.998 @383756409 CHRE_AR_RESULT reason=3, sampleCount=0, transitionCount=0
    08-16 17:44:52.999 @383756410 ACTIVITY_DETECTION_RESULT ActivityRecognitionResult [probableActivities=[DetectedActivity [type=STILL, confidence=100]], timeMillis=1660697092998, elapsedRealtimeMillis=383756409] sentToClient=true

So it looks like we are in fact reading locations for a while and then we start the activity transition. So why does this not trigger the geofence? I don't understand. #$#%#$ closed source software...

shankari commented 2 years ago

So it looks like enabling activity transitions or significant motion changes might help us re-implement the geofence. But why do we even need to do this?

First, it is pretty clear that all of this is in Google Play Services. Looking at Google Play Services versions, both my personal phone and the pixel have the same version (22.26.15). This was uploaded to the apk websites around July 19, 2022 (https://www.apkmirror.com/apk/google-inc/google-play-services/google-play-services-22-26-15-release/google-play-services-22-26-15-100400-461192076-3-android-apk-download/) so it makes sense that the update may have reached the phones only at the end of July.

But why isn't this happening on other phones?

Concretely, my husband also has Google Play Services version 22.26.15 and he apparently misses no more than one trip a week.

shankari commented 2 years ago

Final investigation into a time that actually worked:

5:34pm arrived at Office Depot 6:01pm outside Office Depot

Transition was detected at 17:54

  #239: act=local.transition.exited_geofence flg=0x10 pkg=gov.nrel.cims.openpath
    +49ms dispatch +37ms finish
    enq=2022-08-14 17:54:50.172 disp=2022-08-14 17:54:50.221 fin=2022-08-14 17:54:50.258
  #243: act=local.transition.exited_geofence flg=0x10 pkg=gov.colorado.energyoffice.emission
    +1ms dispatch +100ms finish
    enq=2022-08-14 17:54:50.120 disp=2022-08-14 17:54:50.121 fin=2022-08-14 17:54:50.221

but at the time that we recorded the logs, it was showing unavailable

     rec[0]: time=08-14 18:10:23.829 processed=UnavailableActivityState org=UnavailableActivityState dest=<null> what=SM_LOCATION_CMD
     rec[1]: time=08-14 18:10:25.566 processed=UnavailableActivityState org=UnavailableActivityState dest=<null> what=SM_AR_DEEP_STILL_MODE
     rec[2]: time=08-14 18:10:28.526 processed=UnavailableActivityState org=UnavailableActivityState dest=<null> what=SM_LOCATION_CMD
     rec[3]: time=08-14 18:10:28.529 processed=UnavailableActivityState org=UnavailableActivityState dest=<null> what=SM_AR_DEEP_STILL_MODE
     rec[4]: time=08-14 18:10:34.164 processed=UnavailableActivityState org=UnavailableActivityState dest=<null> what=SM_LOCATION_CMD
     rec[5]: time=08-14 18:10:40.792 processed=UnavailableActivityState org=UnavailableActivityState dest=<null> what=SM_LOCATION_CMD
     rec[6]: time=08-14 18:10:47.648 processed=UnavailableActivityState org=UnavailableActivityState dest=<null> what=SM_LOCATION_CMD
     rec[7]: time=08-14 18:10:47.648 processed=UnavailableActivityState org=UnavailableActivityState dest=<null> what=SM_LOCATION_AVAILABILITY_CHANGED
     rec[8]: time=08-14 18:11:10.544 processed=UnavailableActivityState org=UnavailableActivityState dest=<null> what=SM_SYSTEM_EVENT_CMD
     rec[9]: time=08-14 18:13:35.624 processed=UnavailableActivityState org=UnavailableActivityState dest=<null> what=SM_SYSTEM_EVENT_CMD

Unfortunately, it looks like these logs are only generated for a very short time. The log was generated at dumpstate: 2022-08-14 18:09:48 and it has the activity logs for 18:10 to 18:13 and the activity detection logs in the locationmanager from

    08-14 18:08:14.123 @3309574893 ACTIVITY_DETECTION_RESULT ActivityRecognitionResult [probableActivities=[DetectedActivity [type=STILL, confidence=63], DetectedActivity [type=ON_FOOT, confidence=21], DetectedActivity [type=WALKING, confidence=21], DetectedActivity [type=IN_VEHICLE, confidence=6], DetectedActivity [type=IN_ROAD_VEHICLE, confidence=6], DetectedActivity [type=IN_RAIL_VEHICLE, confidence=6], DetectedActivity [type=19, confidence=6], DetectedActivity [type=20, confidence=6], DetectedActivity [type=ON_BICYCLE, confidence=2], DetectedActivity [type=UNKNOWN, confidence=2]], timeMillis=1660525693987, elapsedRealtimeMillis=3309574757] sentToClient=true
...
    08-14 18:10:42.736 @3309723506 ACTIVITY_DETECTION_RESULT ActivityRecognitionResult [probableActivities=[DetectedActivity [type=UNKNOWN, confidence=40], DetectedActivity [type=IN_VEHICLE, confidence=10], DetectedActivity [type=ON_BICYCLE, confidence=10], DetectedActivity [type=ON_FOOT, confidence=10], DetectedActivity [type=WALKING, confidence=10], DetectedActivity [type=RUNNING, confidence=10], DetectedActivity [type=STILL, confidence=10], DetectedActivity [type=IN_ROAD_VEHICLE, confidence=10], DetectedActivity [type=IN_RAIL_VEHICLE, confidence=10], DetectedActivity [type=19, confidence=10], DetectedActivity [type=20, confidence=10]], timeMillis=1660525832003, elapsedRealtimeMillis=3309712774] sentToClient=true

shankari commented 2 years ago

Generated full logcat logs from both phones on the way to karate

Test pixel phone worked

system logs started at 08-17 06:05:27.061, main logs started at 08-17 16:47:33.173

Fortunately, geofence exit was after the main logging started, around Shoreline and California.

--------- beginning of crash
--------- beginning of system
--------- beginning of main
08-17 16:47:34.401  8299  7130 D GeofenceExitIntentService: geofence exit intent action = null
08-17 16:47:34.407  8299  7130 D GeofenceExitIntentService: got geofence intent callback with type 2 and location Location[fused (shoreline, between Mercy and California) hAcc=31.167 et=+5d9h38m37s246ms alt=-6.299999713897705 vAcc=2.299716]

Let's look at the logs right before that. Not quite sure when I picked up the phone, but this is the first time I connected to ADB. At the time, I had still not started the car.

08-17 16:42:28.004  1858  3369 D AdbDebuggingManager: Received public key:

Then, we disconnected and reconnected

08-17 16:43:50.635  1858  3369 W AdbDebuggingManager: Read failed with count -1
...
08-17 16:43:55.804  1858  6832 D AdbDebuggingManager: Received public key:
...
08-17 16:44:18.206  1858  6832 D AdbDebuggingManager: Received disconnected message:
...
08-17 16:44:18.206  1858  6832 D AdbDebuggingManager: Received public key:

So it is enough if we look for logs between 16:42 and 16:47 to see if we can figure out how the geofence exit was triggered.

shankari commented 2 years ago

the relevant logs seem to be

08-17 16:42:40.820  1858  6147 W AppOps  : Noting op not finished: uid 10320 pkg gov.nrel.cims.openpath code 79 startTime of in progress event=1660719976128

08-17 16:47:33.167  1858  2194 W BroadcastQueue: Target SDK mismatch: receiver ActivityInfo{b25f46d com.google.android.apps.photos.actionqueue.impl.SystemReceiver} targets 33 but delivery restricted to [0, 23] broadcasting Intent { act=android.net.conn.CONNECTIVITY_CHANGE flg=0x4200010 (has extras) } from android (pid=1858, uid=1000) to com.google.android.apps.photos/.actionqueue.impl.SystemReceiver
08-17 16:47:33.168  1858  2194 W BroadcastQueue: Target SDK mismatch: receiver ActivityInfo{8f078a2 com.google.android.apps.photos.jobqueue.JobServiceBroadcastReceiver} targets 33 but delivery restricted to [0, 23] broadcasting Intent { act=android.net.conn.CONNECTIVITY_CHANGE flg=0x4200010 (has extras) } from android (pid=1858, uid=1000) to com.google.android.apps.photos/.jobqueue.JobServiceBroadcastReceiver
08-17 16:47:33.168  1858  2194 W BroadcastQueue: Target SDK mismatch: receiver ActivityInfo{270e933 com.google.android.gms.gcm.ServiceAutoStarter} targets 33 but delivery restricted to [0, 23] broadcasting Intent { act=android.net.conn.CONNECTIVITY_CHANGE flg=0x4200010 (has extras) } from android (pid=1858, uid=1000) to com.google.android.gms/.gcm.ServiceAutoStarter

and then we switch to main logs, which have a WiFi scan

--------- beginning of main
...
08-17 16:47:34.302  1428  7120 D LOWI-8.6.0.75: [LOWI-Scan] do_listen_events: Rcvd valid Netlink Cmd 34 Err 0
08-17 16:47:34.302  1858  3600 D WifiNl80211Manager: Scan result ready event
08-17 16:47:34.302  1858  3600 D WifiNative: Scan result ready event
08-17 16:47:34.304  1428  7120 D LOWI-8.6.0.75: [LOWI-Scan]
08-17 16:47:34.302  1858  3600 D WifiNl80211Manager: Scan result ready event
08-17 16:47:34.302  1858  3600 D WifiNative: Scan result ready event
08-17 16:47:34.304  1428  7120 D LOWI-8.6.0.75: [LOWI-Scan]
08-17 16:47:34.304  1428  7120 D LOWI-8.6.0.75: [LOWI-Scan] print_bss_handler: Report beacon TSF 466713679639 as it greater than probe TSF 466713679639
...
08-17 16:47:34.304  1428  7120 D LOWI-8.6.0.75: [LOWI-Scan] print_bss_handler: Report beacon TSF 466713792132 as it greater than probe TSF 466713792132
...
08-17 16:47:34.312  1428  7120 D LOWI-8.6.0.75: [LOWIScanResultReceiver] Send scan meas to listener
08-17 16:47:34.312  1428  7120 D LOWI-8.6.0.75: [LOWIScanResultReceiver] Enter passive listening mode
08-17 16:47:34.322  1428  1481 D LOWI-8.6.0.75: [LOWIController] processMeasurementResults: No current Request. Cache measurements
...
08-17 16:47:34.322  1428  1481 D LOWI-8.6.0.75: [LOWIControllerExtn] sendLOWILpDiscoveryScanResponse: Not a discovery scan response
08-17 16:47:34.394  8299  8299 D GeofenceExitIntentService: onCreate called

Is that the reason? Why did it not work on my personal phone then? What was my personal phone doing around 16:47?

shankari commented 2 years ago

Lots of crashes in the Sprint Carrier Device Manager

08-16 15:05:07.051  4437  4526 E AndroidRuntime: java.lang.NoClassDefFoundError: c.b.a.a.i.H.a
08-16 15:05:07.051  4437  4526 E AndroidRuntime:    at c.b.a.a.i.H.a.a(PriorityMapping.java:1)
08-16 15:05:07.051  4437  4526 E AndroidRuntime:    at c.b.a.a.i.F.h.G.s(SQLiteEventStore.java:4)
08-16 15:05:07.051  4437  4526 E AndroidRuntime:    at c.b.a.a.i.F.h.G.b0(SQLiteEventStore.java:5)
08-16 15:05:07.051  4437  4526 E AndroidRuntime:    at c.b.a.a.i.F.h.x.a(Unknown Source:8)
08-16 15:05:07.051  4437  4526 E AndroidRuntime:    at c.b.a.a.i.F.h.G.y(SQLiteEventStore.java:3)
08-16 15:05:07.051  4437  4526 E AndroidRuntime:    at c.b.a.a.i.F.h.G.N(SQLiteEventStore.java:6)
08-16 15:05:07.051  4437  4526 E AndroidRuntime:    at c.b.a.a.i.F.c.b(DefaultScheduler.java:1)
08-16 15:05:07.051  4437  4526 E AndroidRuntime:    at c.b.a.a.i.F.b.g(Unknown Source:6)
08-16 15:05:07.051  4437  4526 E AndroidRuntime:    at c.b.a.a.i.F.h.G.a(SQLiteEventStore.java:3)
08-16 15:05:07.051  4437  4526 E AndroidRuntime:    at c.b.a.a.i.F.c.c(DefaultScheduler.java:8)
08-16 15:05:07.051  4437  4526 E AndroidRuntime:    at c.b.a.a.i.F.a.run(Unknown Source:8)
08-16 15:05:07.051  4437  4526 E AndroidRuntime:    at c.b.a.a.i.r.run(SafeLoggingExecutor.java:1)
08-16 15:05:07.051  4437  4526 E AndroidRuntime:    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
08-16 15:05:07.051  4437  4526 E AndroidRuntime:    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
08-16 15:05:07.051  4437  4526 E AndroidRuntime:    at java.lang.Thread.run(Thread.java:919)

shankari commented 2 years ago

There was a location scan at around 16:39 and a Wifi scan at around 16:45, some "too large data" messages.

08-17 16:39:14.712 19855 19855 W ActivityThread: serviceStart lasts for 19902 ms, ServiceArgsData = ServiceArgsData{token=android.os.BinderProxy@d47294e startId=812 args=Intent { act=com.google.android.location.internal.action.FLP_LOW_POWER_LOCATION_RESULT pkg=com.google.android.gms cmp=com.google.android.gms/com.google.android.location.internal.PendingIntentCallbackService (has extras) }}
08-17 16:45:57.298  1163  1163 I wificond: Pno scan started for frequencies: 2412, 2417, 2422, 2427, 2432, 2437, 2447, 2452, 2457, 2462, 5180, 5200, 5220, 5240, 5745, 5765, 5785, 5805,
08-17 16:45:59.201 19855 20107 W Binder  : reply too large data on java level: InterfaceDescriptor = null, code = 1
08-17 16:46:00.707 19855 20107 W Binder  : reply too large data on java level: InterfaceDescriptor = null, code = 1
08-17 16:58:29.913  1684  3884 D ConnectivityService: Returning BLOCKED NetworkInfo to uid=10272
08-17 17:00:56.244  1684  1722 W BatteryExternalStatsWorker: modem info is invalid: ModemActivityInfo{ mTimestamp=3564737007 mSleepTimeMs=-1880648785 mIdleTimeMs=948785403 mTxTimeMs[]=[718595, 434235, 997879, 5854031, 1675018] mRxTimeMs=191541034 mEnergyUsed=0}

but main only started at 17:01, so the logs were missing

--------- beginning of main
08-17 17:01:26.950  1684  3876 I BatteryStatsService: In wakeup_callback: resumed from suspend

shankari commented 2 years ago

when the geofence did exit, it was at 17:18. So the geofence exit detection logs should be in the minutes before that.

08-17 17:18:57.581 25387 25387 I TripDiaryStateMachineRcvr: TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@97ce682, Intent { act=local.transition.exited_geofence flg=0x10 pkg=gov.colorado.energyoffice.emission cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineReceiver }) called

Look at the system logs after 17:01, we get a bunch of expiring lines, fingerprint checker, and a few data too large

``` 08-17 17:09:37.036 4015 4015 V FingerprintManager: touchFodMandatory motionEvent:MotionEvent { action=ACTION_MOVE, actionButton=0, id[0]=0, x[0]=526.0, y[0]=609.0, toolType[0]=TOOL_TYPE_FINGER, id[1]=1, x[1]=383.0, y[1]=589.0, toolType[1]=TOOL_TYPE_FINGER, buttonState=0, classification=NONE, metaState=0, flags=0x0, edgeFlags=0x0, pointerCount=2, historySize=1, eventTime=781646099, downTime=781645777, deviceId=7, source=0x1002, displayId=0 } by (com.motorola.motodisplay) 08-17 17:09:48.533 1163 1163 I wificond: Pno scan started for frequencies: 2412, 2417, 2422, 2427, 2432, 2437, 2447, 2452, 2457, 2462, 5180, 5200, 5220, 5240, 5745, 5765, 5785, 5805, 08-17 17:10:01.588 1163 1163 I wificond: Pno scan started for frequencies: 2412, 2417, 2422, 2427, 2432, 2437, 2447, 2452, 2457, 2462, 5180, 5200, 5220, 5240, 5745, 5765, 5785, 5805, 08-17 17:11:05.928 1163 1163 I wificond: Pno scan started for frequencies: 2412, 2417, 2422, 2427, 2432, 2437, 2447, 2452, 2457, 2462, 5180, 5200, 5220, 5240, 5745, 5765, 5785, 5805, 08-17 17:12:41.756 19855 21189 W Binder : reply too large data on java level: InterfaceDescriptor = null, code = 1 ``` then we get to the main logs ``` 08-17 17:12:42.882 8579 8579 D OtaApp : PollingMangerService, phone state: {mVoiceRegState=0(IN_SERVICE), mDataRegState=0(IN_SERVICE), mVideoRegState=1(OUT_OF_SERVICE), mChannelNumber=41292, duplexMode()=2, mCellBandwidths=[20000, 20000], mVoiceOperatorAlphaLong=null, mVoiceOperatorAlphaShort=null, mDataOperatorAlphaLong=null, mDataOperatorAlphaShort=null, isManualNetworkSelection=false(automatic), getRilVoiceRadioTechnology=14(LTE), getRilDataRadioTechnology=14(LTE), mCssIndicator=supported, mNetworkId=-1, mSystemId=-1, mCdmaRoamingIndicator=-1, mCdmaDefaultRoamingIndicator=-1, mIsEmergencyOnly=false, isUsingCarrierAggregation=false, mLteEarfcnRsrpBoost=0, mNetworkRegistrationInfos=[NetworkRegistrationInfo{ domain=CS transportType=WWAN registrationState=HOME roamingType=NOT_ROAMING accessNetworkTechnology=LTE rejectCause=0 emergencyEnabled=false availableServices=[VOICE,SMS,VIDEO] cellIdentity=null voiceSpecificInfo=VoiceSpecificRegistrationInfo { mCssSupported=true mRoamingIndicator=1 mSystemIsInPrl=-1 mDefaultRoamingIndicator=-1} dataSpecificInfo=null nrState=NONE}, NetworkRegistrationInfo{ domain=PS transportType=WWAN registrationState=HOME roamingType=NOT_ROAMING accessNetworkTechnology=LTE rejectCause=0 emergencyEnabled=false availableServices=[DATA] cellIdentity=null voiceSpecificInfo=null dataSpecificInfo=android.telephony.DataSpecificRegistrationInfo :{ maxDataCalls = 20 isDcNrRestricted = false isNrAvailable = false isEnDcAvailable = false LteVopsSupportInfo : mVopsSupport = 2 mEmcBearerSupport = 2 mIsUsingCarrierAggregation = false } nrState=NONE}], mNrFrequencyRange=-1, mOperatorAlphaLongRaw=Ting, mOperatorAlphaShortRaw=Ting, mIsIwlanPreferred=false, mIsCdmaFemtoCell=false, mIsLteFemtoCell=false, mIsOnCsgCell=false, mCsgId=-1, mCsgName=null} ... 08-17 17:12:42.896 18285 18285 D CellBroadcastReceiver: onReceive Intent { act=android.intent.action.SERVICE_STATE flg=0x1000010 cmp=com.android.cellbroadcastreceiver/.CellBroadcastReceiver (has extras) } ... 08-17 17:12:43.031 2580 3458 D QCNEJ/WwanInfoRelay: onServiceStateChanged: dataState: 2 DDS:1 Notify service state update ... 08-17 17:12:43.050 18285 18285 D CellBroadcastReceiver: onReceive Intent { act=android.intent.action.SERVICE_STATE flg=0x1000010 cmp=com.android.cellbroadcastreceiver/.CellBroadcastReceiver (has extras) } ... 08-17 17:13:14.290 19855 19855 I NearbyDiscovery: FastPairDisplayObserver: STATE_OFF -> STATE_ON [CONTEXT service_id=49 ] ... 08-17 17:13:21.415 14689 14689 I wpa_supplicant: wlan0: CTRL-EVENT-AVOID-FREQ ranges=5180-5320 08-17 17:13:21.417 14689 14689 I wpa_supplicant: wlan0: CTRL-EVENT-REGDOM-CHANGE init=DRIVER type=COUNTRY alpha2=US 08-17 17:13:21.419 1218 1218 I cnss-daemon: nl80211 response handler invoked 08-17 17:13:21.419 1218 1218 I cnss-daemon: nl80211_response_handler: cmd 103, vendorID 4980, subcmd 10 received ... 08-17 17:13:28.603 19321 19350 W bile.echolocat: ClassLoaderContext shared library size mismatch. Expected=0, found=2 (DLC[];PCL[/data/app/com.tmobile.echolocate-qzjEPvlJURnXWuEKZEO7nA==/base.apk*3046549445:/data/app/com.tmobile.echolocate-qzjEPvlJURnXWuEKZEO7nA==/base.apk!classes2.dex*801456077:/data/app/com.tmobile.echolocate-qzjEPvlJURnXWuEKZEO7nA==/base.apk!classes3.dex*1381874296] | DLC[];PCL[/data/app/com.tmobile.echolocate-qzjEPvlJURnXWuEKZEO7nA==/base.apk*3046549445:/data/app/com.tmobile.echolocate-qzjEPvlJURnXWuEKZEO7nA==/base.apk!classes2.dex*801456077:/data/app/com.tmobile.echolocate-qzjEPvlJURnXWuEKZEO7nA==/base.apk!classes3.dex*1381874296]{PCL[/system/framework/android.test.runner.jar*3312018701]{PCL[/system/framework/android.test.base.jar*1299883780]#PCL[/system/framework/android.test.mock.jar*3601177991]{PCL[/system/framework/android.test.base.jar*1299883780]}}#PCL[/system/framework/android.test.mock.jar*3601177991]{PCL[/system/framework/android.test.base.jar*1299883780]}}) 08-17 17:13:28.607 19321 19350 W bile.echolocat: Found duplicate classes, falling back to extracting from APK : /data/user_de/0/com.google.android.gms/app_chimera/m/000000b7/MeasurementDynamite.apk 08-17 17:13:28.607 19321 19350 W bile.echolocat: NOTE: This wastes RAM and hurts startup performance. 08-17 17:13:28.608 19321 19350 W bile.echolocat: Found duplicated class when checking oat files: 'La;' in /data/user_de/0/com.google.android.gms/app_chimera/m/000000b7/MeasurementDynamite.apk and /data/app/com.tmobile.echolocate-qzjEPvlJURnXWuEKZEO7nA==/base.apk!classes2.dex 08-17 17:13:28.608 19321 19350 W bile.echolocat: 08-17 17:13:28.843 19321 19396 I FA : App measurement initialized, version: 66000 08-17 17:13:28.843 19321 19396 I FA : To enable debug logging run: adb shell setprop log.tag.FA VERBOSE 08-17 17:13:28.843 19321 19396 I FA : To enable faster debug mode event logging run: 08-17 17:13:28.843 19321 19396 I FA : adb shell setprop debug.firebase.analytics.app com.tmobile.echolocate ... 08-17 17:16:29.570 1684 2060 D BatteryService: uevent={POWER_SUPPLY_DP_DM=0, POWER_SUPPLY_VOLTAGE_QNOVO=-22, POWER_SUPPLY_VOLTAGE_NOW=4101196, POWER_SUPPLY_SW_JEITA_ENABLED=0, POWER_SUPPLY_FORCE_RECHARGE=0, POWER_SUPPLY_CHARGE_CONTROL_LIMIT_MAX=8, POWER_SUPPLY_RECHARGE_SOC=99, POWER_SUPPLY_HEALTH=Good, POWER_SUPPLY_TECHNOLOGY=Li-ion, POWER_SUPPLY_CHARGER_TEMP_MAX=160, POWER_SUPPLY_FCC_STEPPER_ENABLE=0, SEQNUM=1629535, POWER_SUPPLY_INPUT_CURRENT_LIMITED=1, POWER_SUPPLY_CHARGE_CONTROL_LIMIT=0, POWER_SUPPLY_STATUS=Charging, POWER_SUPPLY_CYCLE_COUNT=5, POWER_SUPPLY_BATTERY_CHARGING_ENABLED=1, POWER_SUPPLY_CURRENT_MAX=2000000, POWER_SUPPLY_CHARGE_TERM_CURRENT=-102, POWER_SUPPLY_CAPACITY=57, DEVPATH=/devices/platform/soc/1c40000.qcom,spmi/spmi-0/spmi0-02/1c40000.qcom,spmi:qcom,pmi632@2:qcom,qpnp-smb5/power_supply/battery, POWER_SUPPLY_CHARGE_DONE=0, POWER_SUPPLY_CHARGE_TYPE=Fast, POWER_SUPPLY_CHARGER_TEMP=455, POWER_SUPPLY_CHARGE_RATE=Normal, POWER_SUPPLY_CURRENT_QNOVO=-22, POWER_SUPPLY_CURRENT_NOW=1444550, POWER_SUPPLY_SYSTEM_TEMP_LEVEL=0, POWER_SUPPLY_PRESENT=1, POWER_SUPPLY_PARALLEL_DISABLE=0, POWER_SUPPLY_CHARGE_FULL=5003000, POWER_SUPPLY_CONSTANT_CHARGE_CURRENT=2000000, SUBSYSTEM=power_supply, POWER_SUPPLY_SET_SHIP_MODE=0, POWER_SUPPLY_TEMP=369, ACTION=change, POWER_SUPPLY_RERUN_AICL=0, POWER_SUPPLY_AGE=99, POWER_SUPPLY_NAME=battery, POWER_SUPPLY_VOLTAGE_MAX=-22, POWER_SUPPLY_CONSTANT_CHARGE_CURRENT_MAX=2000000, POWER_SUPPLY_CHARGE_COUNTER=3001800, POWER_SUPPLY_STEP_CHARGING_ENABLED=0, POWER_SUPPLY_NUM_SYSTEM_TEMP_LEVELS=8, POWER_SUPPLY_DIE_HEALTH=Cool, POWER_SUPPLY_INPUT_SUSPEND=0} ... 08-17 17:18:54.270 1684 2060 D BatteryService: uevent={POWER_SUPPLY_DP_DM=0, POWER_SUPPLY_VOLTAGE_QNOVO=-22, POWER_SUPPLY_VOLTAGE_NOW=3963003, POWER_SUPPLY_SW_JEITA_ENABLED=0, POWER_SUPPLY_FORCE_RECHARGE=0, POWER_SUPPLY_CHARGE_CONTROL_LIMIT_MAX=8, POWER_SUPPLY_RECHARGE_SOC=99, POWER_SUPPLY_HEALTH=Good, POWER_SUPPLY_TECHNOLOGY=Li-ion, POWER_SUPPLY_CHARGER_TEMP_MAX=160, POWER_SUPPLY_FCC_STEPPER_ENABLE=0, SEQNUM=1629576, POWER_SUPPLY_INPUT_CURRENT_LIMITED=0, POWER_SUPPLY_CHARGE_CONTROL_LIMIT=0, POWER_SUPPLY_STATUS=Discharging, POWER_SUPPLY_CYCLE_COUNT=5, POWER_SUPPLY_BATTERY_CHARGING_ENABLED=1, POWER_SUPPLY_CURRENT_MAX=2000000, POWER_SUPPLY_CHARGE_TERM_CURRENT=-102, POWER_SUPPLY_CAPACITY=59, DEVPATH=/devices/platform/soc/1c40000.qcom,spmi/spmi-0/spmi0-02/1c40000.qcom,spmi:qcom,pmi632@2:qcom,qpnp-smb5/power_supply/battery, POWER_SUPPLY_CHARGE_DONE=0, POWER_SUPPLY_CHARGE_TYPE=N/A, POWER_SUPPLY_CHARGE_RATE=None, POWER_SUPPLY_CURRENT_QNOVO=-22, POWER_SUPPLY_CURRENT_NOW=-123596, POWER_SUPPLY_SYSTEM_TEMP_LEVEL=0, POWER_SUPPLY_PRESENT=1, POWER_SUPPLY_PARALLEL_DISABLE=0, POWER_SUPPLY_CHARGE_FULL=5003000, POWER_SUPPLY_CONSTANT_CHARGE_CURRENT=2000000, SUBSYSTEM=power_supply, POWER_SUPPLY_SET_SHIP_MODE=0, POWER_SUPPLY_TEMP=403, ACTION=change, POWER_SUPPLY_RERUN_AICL=0, POWER_SUPPLY_AGE=99, POWER_SUPPLY_NAME=battery, POWER_SUPPLY_VOLTAGE_MAX=-22, POWER_SUPPLY_CONSTANT_CHARGE_CURRENT_MAX=2000000, POWER_SUPPLY_CHARGE_COUNTER=3051830, POWER_SUPPLY_STEP_CHARGING_ENABLED=0, POWER_SUPPLY_NUM_SYSTEM_TEMP_LEVELS=8, POWER_SUPPLY_DIE_HEALTH=Unknown, POWER_SUPPLY_INPUT_SUSPEND=0} 08-17 17:18:54.292 1684 1726 I PowerManagerService: Waking up from Dozing (uid=1000, reason=WAKE_REASON_PLUGGED_IN, details=android.server.power:PLUGGED:false)... ... 08-17 17:18:54.293 1684 1717 W BroadcastQueue: Background execution not allowed: receiving Intent { act=android.intent.action.ACTION_POWER_DISCONNECTED flg=0x4000010 (has extras) } to com.google.android.gms/.chimera.GmsIntentOperationService$PersistentTrustedReceiver ... 08-17 17:18:54.725 8579 8579 D OtaApp : PollingMangerService, phone state: {mVoiceRegState=0(IN_SERVICE), mDataRegState=0(IN_SERVICE), mVideoRegState=1(OUT_OF_SERVICE), mChannelNumber=66786, duplexMode()=1, mCellBandwidths=[20000], mVoiceOperatorAlphaLong=null, mVoiceOperatorAlphaShort=null, mDataOperatorAlphaLong=null, mDataOperatorAlphaShort=null, isManualNetworkSelection=false(automatic), getRilVoiceRadioTechnology=14(LTE), getRilDataRadioTechnology=14(LTE), mCssIndicator=supported, mNetworkId=-1, mSystemId=-1, mCdmaRoamingIndicator=-1, mCdmaDefaultRoamingIndicator=-1, mIsEmergencyOnly=false, isUsingCarrierAggregation=false, mLteEarfcnRsrpBoost=0, mNetworkRegistrationInfos=[NetworkRegistrationInfo{ domain=CS transportType=WWAN registrationState=HOME roamingType=NOT_ROAMING accessNetworkTechnology=LTE rejectCause=0 emergencyEnabled=false availableServices=[VOICE,SMS,VIDEO] cellIdentity=null voiceSpecificInfo=VoiceSpecificRegistrationInfo { mCssSupported=true mRoamingIndicator=1 mSystemIsInPrl=-1 mDefaultRoamingIndicator=-1} dataSpecificInfo=null nrState=NONE}, NetworkRegistrationInfo{ domain=PS transportType=WWAN registrationState=HOME roamingType=NOT_ROAMING accessNetworkTechnology=LTE rejectCause=0 emergencyEnabled=false availableServices=[DATA] cellIdentity=null voiceSpecificInfo=null dataSpecificInfo=android.telephony.DataSpecificRegistrationInfo :{ maxDataCalls = 20 isDcNrRestricted = false isNrAvailable = false isEnDcAvailable = false LteVopsSupportInfo : mVopsSupport = 2 mEmcBearerSupport = 2 mIsUsingCarrierAggregation = false } nrState=NONE}], mNrFrequencyRange=-1, mOperatorAlphaLongRaw=Ting, mOperatorAlphaShortRaw=Ting, mIsIwlanPreferred=false, mIsCdmaFemtoCell=false, mIsLteFemtoCell=false, mIsOnCsgCell=false, mCsgId=-1, mCsgName=null} 08-17 17:18:54.772 18285 18285 D CellBroadcastReceiver: onReceive Intent { act=android.intent.action.SERVICE_STATE flg=0x1000010 cmp=com.android.cellbroadcastreceiver/.CellBroadcastReceiver (has extras) } 08-17 17:18:55.274 1684 7708 D ConnectivityService: requestNetwork for uid/pid:10226/19522 NetworkRequest [ TRACK_DEFAULT id=15373, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED Uid: 10226] ] 08-17 17:18:55.276 2640 2640 D PhoneSwitcherNetworkRequstListener: got request NetworkRequest [ TRACK_DEFAULT id=15373, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED Uid: 10226] ] with score 50 and serial 3 08-17 17:18:55.277 1684 2176 D WifiNetworkFactory: got request NetworkRequest [ TRACK_DEFAULT id=15373, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED Uid: 10226] ] with score 50 and serial 3 08-17 17:18:55.277 1684 2176 D UntrustedWifiNetworkFactory: got request NetworkRequest [ TRACK_DEFAULT id=15373, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED Uid: 10226] ] with score 50 and serial 3 08-17 17:18:55.299 1684 3889 D ConnectivityService: requestNetwork for uid/pid:10226/19522 NetworkRequest [ TRACK_DEFAULT id=15374, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED Uid: 10226] ] 08-17 17:18:55.300 1684 2281 D Ethernet: got request NetworkRequest [ TRACK_DEFAULT id=15374, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED Uid: 10226] ] with score 50 and serial 3 08-17 17:18:55.300 1684 2176 D WifiNetworkFactory: got request NetworkRequest [ TRACK_DEFAULT id=15374, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED Uid: 10226] ] with score 50 and serial 3 08-17 17:18:55.300 1684 2176 D UntrustedWifiNetworkFactory: got request NetworkRequest [ TRACK_DEFAULT id=15374, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED Uid: 10226] ] with score 50 and serial 3 08-17 17:18:55.301 2640 2640 D PhoneSwitcherNetworkRequstListener: got request NetworkRequest [ TRACK_DEFAULT id=15374, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED Uid: 10226] ] with score 50 and serial 3 ```

And then right before the geofence exit, we get

08-17 17:18:54.292  1684  1726 I PowerManagerService: Waking up from Dozing (uid=1000, reason=WAKE_REASON_PLUGGED_IN, details=android.server.power:PLUGGED:false)...
...
08-17 17:18:56.352  1684  1703 I UsbPortManager: USB port changed: port=UsbPort{id=port0, supportedModes=dualsupportedContaminantProtectionModes=0supportsEnableContaminantPresenceProtection=falsesupportsEnableContaminantPresenceDetection=false, status=UsbPortStatus{connected=false, currentMode=none, currentPowerRole=no-power, currentDataRole=no-data, supportedRoleCombinations=[no-power:no-data], contaminantDetectionStatus=0, contaminantProtectionStatus=0}, canChangeMode=true, canChangePowerRole=false, canChangeDataRole=false, connectedAtMillis=0, lastConnectDurationMillis=555154
....
08-17 17:18:57.328  1684  3875 D WificondControl: Scan result ready event
08-17 17:18:57.328  1307  4362 I LOWI-8.6.0.76: [LOWI-Scan] lowi_close_record:Scan done in 3565793986ms, 21 APs in scan results
08-17 17:18:57.331   779   779 I Zygote  : Process 15965 exited due to signal 9 (Killed)
...
08-17 17:18:57.389  4015  4015 I MotoDisplay: Acquiring partial wakelock MotoDisplayWakeLock for 500 ms.
08-17 17:18:57.394  4015  4015 I MotoDisplay: Releasing wakelock: MotoDisplayWakeLock
...
08-17 17:18:57.470  1684  1718 I ActivityManager: Start proc 19816:org.mozilla.firefox:gpu/u0a269 for service {org.mozilla.firefox/org.mozilla.gecko.process.GeckoChildProcessServices$gpu}
08-17 17:18:57.489 19816 19816 E lla.firefox:gp: Not starting debugger since process cannot load the jdwp agent.
08-17 17:18:57.499 25387 25387 D GeofenceExitIntentService: onCreate called

From those logs, I can think of a few different causes, in order of priority:

LOWI-Scan
Waking up from Dozing
Acquiring partial wakelock

And (2) and (3) are likely to be related.

Let's see if these logs appear anywhere else...

shankari commented 2 years ago

Ok, so I can confirm that this is the first instance in the "trip detected at end" logs.

$ grep PowerManagerService personal_phone_karate_trip_at_destination.log
08-17 17:18:54.292  1684  1726 I PowerManagerService: Waking up from Dozing (uid=1000, reason=WAKE_REASON_PLUGGED_IN, details=android.server.power:PLUGGED:false)...
08-17 17:18:54.579  1684  1726 W PowerManagerService: Screen on took 288 ms
08-17 17:19:43.138  1684  1726 I PowerManagerService: Waking up from Awake (uid=1000, reason=WAKE_REASON_PLUGGED_IN, details=android.server.power:PLUGGED:true)...
08-17 17:19:46.587  1684  1704 I PowerManagerService: Going to sleep due to power_button (uid 1000)...
08-17 17:19:47.224  1684  1726 I PowerManagerService: Dozing...
08-17 17:19:47.583  1684  2125 I PowerManagerService: Waking up from Dozing (uid=1000, reason=WAKE_REASON_POWER_BUTTON, details=android.policy:POWER)...
08-17 17:19:47.767  1684  3876 I PowerManagerService: Waking up from Awake (uid=10145, reason=WAKE_REASON_GESTURE, details=com.android.systemui:NODOZE)...
08-17 17:20:34.242  1684  1726 I PowerManagerService: Going to sleep due to timeout (uid 1000)...
08-17 17:20:34.992  1684  1726 I PowerManagerService: Dozing...

How about the time that we were leaving?

$ grep PowerManagerService personal_phone_missing_home_to_karate_logcat.log
08-17 17:09:41.683  1684  1726 I PowerManagerService: Waking up from Dozing (uid=1000, reason=WAKE_REASON_PLUGGED_IN, details=android.server.power:PLUGGED:true)...
08-17 17:09:47.855  1684  1704 I PowerManagerService: Going to sleep due to power_button (uid 1000)...
08-17 17:09:48.470  1684  2125 I PowerManagerService: Waking up from Dozing (uid=1000, reason=WAKE_REASON_POWER_BUTTON, details=android.policy:POWER)...
08-17 17:09:48.723  1684  1726 W PowerManagerService: Screen on took 257 ms
08-17 17:10:00.740  1684  1704 I PowerManagerService: Going to sleep due to power_button (uid 1000)...
08-17 17:10:01.402  1684  1726 I PowerManagerService: Dozing...
08-17 17:10:09.088  1684  2125 I PowerManagerService: Waking up from Dozing (uid=1000, reason=WAKE_REASON_POWER_BUTTON, details=android.policy:POWER)...
08-17 17:10:09.104  1684  2055 I PowerManagerService: Waking up from Awake (uid=10145, reason=WAKE_REASON_GESTURE, details=com.android.systemui:NODOZE)...
08-17 17:11:05.015  1684  1726 I PowerManagerService: Going to sleep due to timeout (uid 1000)...
08-17 17:11:05.735  1684  1726 I PowerManagerService: Dozing...

Definitely dozing the entire time.

Could this be it? Could it be doze mode and the wake lock? But:

doze mode has been around since android 6 and we have tested for years with it, without any problems.
And the wakelock was from MotoDisplay
And we have tested by waking up from dozing using the power button to check the notification status and it hasn't helped.

Regardless, will try to stay off doze mode during the trip today and see what it does.

shankari commented 2 years ago

Now that we have investigated to the extent possible, we need to decide what to do.

Since this is happening on both pixel and motorola, it seems unlikely that the error is due to any motorola-specific restrictions
It also seems unlikely to be related to doze mode, since we have not seen it before in many years of testing on android 6+ phones

Note however that the trip back from karate was not recorded yesterday on the test pixel phone (which was not plugged in), while it was recorded on my personal phone which was plugged in. So maybe it is related to doze mode after all.

But even if it is, we have to work around it. We cannot require that people turn off doze mode, or carry their phones around plugged in all the time.

The most obvious workaround is to actually build in a geofence replacement. The most obvious geofence replacement, which requires the least effort from our side, is to use the significant motion changes API.

shankari commented 2 years ago

significant motion changes API:

It triggers when an event occurs and then automatically disables itself. The sensor continues to operate while the device is asleep and will automatically wake the device to notify when significant motion is detected. The application does not need to hold any wake locks for this sensor to trigger. This is a wake up sensor.

Non-wake-up sensors are sensors that do not wake the AP out of suspend to report data. While the AP is in suspend mode, the sensors continue to function and generate events, which are put in a hardware FIFO.

In opposition to non-wake-up sensors, wake-up sensors ensure that their data is delivered independently of the state of the AP. While the AP is awake, the wake-up sensors behave like non-wake-up-sensors. When the AP is asleep, wake-up sensors wake up the AP to deliver events.

https://developer.android.com/guide/topics/sensors/sensors_motion

The significant motion sensor triggers an event each time significant motion is detected and then it disables itself. A significant motion is a motion that might lead to a change in the user's location; for example walking, biking, or sitting in a moving car.

This class is the listener used to handle Trigger Sensors. Trigger Sensors are sensors that trigger an event and are automatically disabled.

So it looks like a design option might be:

turn on trigger at the same time as the geofence
when it triggers, see if the distance has been at least 100m from the last created geofence
- if so, move to ongoing_trip
- if not, re-add a listener and stay in waiting_for_trip_start

Open question: how sensitive is this? will we get notifications even when we are just walking around the house or a restaurant or a warehouse?

shankari commented 2 years ago

So the sig motion sensor is null in the emulator. Let's check for that and then deploy on the real device.

Note that there is also a TYPE_MOTION_DETECT and TYPE_STATIONARY_DETECT if we want to experiment with our own geofence.

08-18 22:09:53.903 18927 18927 D SignificantMotionAction: initialized the motion action with context edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineService@64bc8a4 sensor manager android.hardware.SystemSensorManager@94b8609 sig motion null mListener edu.berkeley.eecs.emission.cordova.tracker.location.actions.SignificantMotionActions$GenerateNotification@bf5000e

We should also probably use the activity transition API as a backup...

shankari commented 2 years ago

Made initial changes to just display the sensor trigger as a notification so we can get a sense of how it works.

The significant motion sensor does not work in the emulator, but it does work on a physical phone, at least on the Pixel It looks like we don't have permissions for high sampling rate, so not sure if this will work.

08-19 08:07:49.220  9805 11031 D SignificantMotionAction: initialized the motion action with context edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineService@729622f sensor manager android.hardware.SystemSensorManager@c54171a sig motion {Sensor name="Significant Motion", vendor="Google", version=1, type=17, maxRange=1.0, resolution=1.0, power=0.25, minDelay=-1} mListener edu.berkeley.eecs.emission.cordova.tracker.location.actions.SignificantMotionActions$GenerateNotification@6f3f24b 
08-19 08:07:49.222  9805 11031 D SignificantMotionAction: Created trigger on the sig motion sensor
08-19 08:07:49.223  1858  6482 W ServiceManager: Permission failure: android.permission.HIGH_SAMPLING_RATE_SENSORS from uid=10291 pid=9805

Also started activity transitions for starting (0) walk, bike, running, and in_vehicle and stopping (1) still (3).

08-19 08:07:49.241  9805 11031 D ActivityTransitionActions: Starting activity transitions for list = [ActivityTransition [mActivityType=7, mTransitionType=0], ActivityTransition [mActivityType=1, mTransitionType=0], ActivityTransition [mActivityType=8, mTransitionType=0], ActivityTransition [mActivityType=0, mTransitionType=0], ActivityTransition [mActivityType=3, mTransitionType=1]]

Don't see any errors or warnings related to that.

shankari commented 2 years ago

High sensing rate is due to not specifying a lower rate while configuring as in https://github.com/linkedin/shaky-android/issues/63

Their fix was to set a lower sensor rate using

     -  sensorManager.registerListener(this, accelerometer,
     -      SensorManager.SENSOR_DELAY_FASTEST);
     + sensorManager.registerListener(this, accelerometer, sensorDelay);

However, we don't use registerListener, we use requestTriggerSensor, which does not allow us to specify the rate.

public boolean requestTriggerSensor (TriggerEventListener listener, Sensor sensor)

So we can test this out, but it might not work, and we may need to just use the activity recognition API after all.

shankari commented 2 years ago

ok so there are 406 of these

$ grep -r "detected significant motion" /tmp/loggerDB.check_activity_transitions.withdate.log | wc -l
     406

Running pretty much continuously until 2:30pm when it stops abruptly

/tmp/loggerDB.check_activity_transitions.withdate.log:22966,1660923650.184,2022-08-19T08:40:50.184000-07:00,NotificationHelper : Generating notify with id 744668466 and message detected significant motion
/tmp/loggerDB.check_activity_transitions.withdate.log:22972,1660923650.295,2022-08-19T08:40:50.295000-07:00,NotificationHelper : Generating notify with id 744668466 and message detected significant motion
/tmp/loggerDB.check_activity_transitions.withdate.log:22978,1660923650.4020002,2022-08-19T08:40:50.402000-07:00,NotificationHelper : Generating notify with id 744668466 and message detected significant motion
/tmp/loggerDB.check_activity_transitions.withdate.log:22998,1660923685.7220001,2022-08-19T08:41:25.722000-07:00,NotificationHelper : Generating notify with id 744668466 and message detected significant motion
/tmp/loggerDB.check_activity_transitions.withdate.log:23004,1660923685.8520002,2022-08-19T08:41:25.852000-07:00,NotificationHelper : Generating notify with id 744668466 and message detected significant motion
/tmp/loggerDB.check_activity_transitions.withdate.log:23010,1660923685.955,2022-08-19T08:41:25.955000-07:00,NotificationHelper : Generating notify with id 744668466 and message detected significant motion
...
/tmp/loggerDB.check_activity_transitions.withdate.log:28649,1660944410.689,2022-08-19T14:26:50.689000-07:00,NotificationHelper : Generating notify with id 744668466 and message detected significant motion
/tmp/loggerDB.check_activity_transitions.withdate.log:28655,1660944429.496,2022-08-19T14:27:09.496000-07:00,NotificationHelper : Generating notify with id 744668466 and message detected significant motion
/tmp/loggerDB.check_activity_transitions.withdate.log:28661,1660944445.784,2022-08-19T14:27:25.784000-07:00,NotificationHelper : Generating notify with id 744668466 and message detected significant motion

Activity transitions were not working because the service wasn't found and so didn't start. Need to fix the name.

08-19 13:28:24.034  1858  2635 W ActivityManager: Unable to start service Intent { cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.ActivityTransitionIntentService (has extras) } U=0: not found
...
08-19 14:13:47.611  1858  3597 W ActivityManager: Unable to start service Intent { cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.ActivityTransitionIntentService (has extras) } U=0: not found
...
08-19 16:55:15.821  1858  6147 W ActivityManager: Unable to start service Intent { cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.ActivityTransitionIntentService (has extras) } U=0: not found

shankari commented 2 years ago

Not sure why it stopped abruptly around 2:30 - there's nothing special in the system logs around that time

08-19 14:24:28.088  1858  3597 W AppOps  : Noting op not finished: uid 10190 pkg com.google.android.gms code 1
13 startTime of in progress event=1660943556477
08-19 14:24:28.094  1858  3597 W AppOps  : Noting op not finished: uid 10190 pkg com.google.android.gms code 1
13 startTime of in progress event=1660943556477
08-19 14:24:28.101  1858  6480 W AppOps  : Noting op not finished: uid 10190 pkg com.google.android.gms code 1
13 startTime of in progress event=1660943556477

08-19 14:27:52.540  1858  6096 W AppOps  : Noting op not finished: uid 10190 pkg com.google.android.gms code 1
13 startTime of in progress event=1660943556477
08-19 14:27:52.545  1858  6096 W AppOps  : Noting op not finished: uid 10190 pkg com.google.android.gms code 1
13 startTime of in progress event=1660944268157
08-19 14:27:52.556  1858  6096 W AppOps  : Noting op not finished: uid 10190 pkg com.google.android.gms code 1
13 startTime of in progress event=1660943556477

and it was definitely not due to installation - this is the first instance of re-installation.

08-19 16:01:30.787  1858  2194 I ActivityManager: Killing 6874:edu.berkeley.eecs.emission/u0a291 (adj 200): st

It is too frequent, and it has that sensor frequency issue, so let's punt on that for now...

shankari commented 2 years ago

so I now saw the ActivityTransitionIntentService notifications as well, and they are pretty responsive as well, the walk transition had turned on by the time I left the front door, for example.

HOWEVER, after the update with the fixes, I also reset the geofence (start + stop trip), and again, e-mission exited the geofence, but none of the other programs did. This was also true on the way back. And we do have some false positives for the activity recognition API.

Given this behavior, I wonder if there's something that is causing the geofences to become invalid after some period of time, and the fix is as simple as resetting the geofence on every periodic sync.

False positives	only emission exited geofence	again, only emission exited geofence	only emission turned on

shankari commented 2 years ago

Aha! I finally see a difference! Initially, the geofencer requests are only for gms and emission, and very rarely for emission

      08-19 08:30:02.947: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10190 com.google.android.gms}]
      08-19 08:30:02.968: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10190 com.google.android.gms}]
      08-19 08:40:50.038: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@30s BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10190 com.google.android.gms}]
      08-19 08:40:50.154: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}]

then we start getting a lot more requests for e-mission (probably after I reinitialized?)

      08-19 10:05:50.031: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}]
      08-19 10:08:58.467: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@1m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}]
      08-19 10:08:58.554: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}]

then we start getting calls for openpath (probably when I reset it) and then high accuracy calls (representing the actual trip)

      08-19 10:26:34.188: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10320 gov.nrel.cims.openpath}]
      08-19 10:26:34.214: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10320 gov.nrel.cims.openpath}]

      08-19 10:31:52.546: +client 10320/gov.nrel.cims.openpath/d537c07f -> Request[@30s HIGH_ACCURACY, minUpdateInterval=5s, waitForAccurateLocation, WorkSource{10320 gov.nrel.cims.openpath}]

Shortly after that, we get geofence requests for openpath, and then high accuracy again

      08-19 10:36:15.556: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}]
      08-19 10:57:09.226: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@1m5s BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}]
      08-19 10:57:10.103: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}]

this continued until around 16:58, when the geofencer checks for openpath stopped

      08-19 16:58:30.348: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}]

after that, we only had checks for GMS until we restarted for emission

      08-19 19:16:10.025: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}]

That's probably why emission was the only one that worked, the others didn't seem to have any valid geofences

shankari commented 2 years ago

concretely, the cims entries were bunched around the time we were moving

``` 08-19 10:26:34.188: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10320 gov.nrel.cims.openpath}] 08-19 10:26:34.214: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10320 gov.nrel.cims.openpath}] 08-19 10:36:15.556: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 10:57:09.226: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@1m5s BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 10:57:10.103: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 11:07:25.337: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 11:19:05.473: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10320 gov.nrel.cims.openpath}] 08-19 11:19:05.520: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 11:19:06.268: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@1m4s BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 11:19:06.304: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 11:19:24.337: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@1m4s BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 11:19:24.375: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 11:37:21.716: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10320 gov.nrel.cims.openpath}] 08-19 11:37:21.877: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 11:40:45.608: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 12:00:33.569: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@6m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 13:03:48.677: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@6m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 13:25:07.120: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 13:41:30.776: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 13:41:30.881: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 14:57:34.361: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 16:15:17.218: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@30s BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 16:58:30.348: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] ```

But the

``` 08-19 08:40:50.154: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}] 08-19 10:05:50.031: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}] 08-19 10:08:58.467: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@1m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}] 08-19 10:08:58.554: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}] 08-19 10:18:13.118: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}] 08-19 10:18:18.091: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@1m11s BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}] 08-19 10:18:18.121: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}] 08-19 10:26:01.105: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@1m11s BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}] 08-19 10:26:01.217: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}] 08-19 10:26:23.085: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@1m11s BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}] 08-19 10:26:23.118: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}] 08-19 10:35:55.301: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}] 08-19 10:35:55.386: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}] 08-19 10:36:15.556: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 10:57:09.226: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@1m5s BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 10:57:10.103: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 11:07:25.337: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 11:19:05.520: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 11:19:06.268: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@1m4s BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 11:19:06.304: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 11:19:24.337: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@1m4s BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 11:19:24.375: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 11:37:21.877: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 11:40:45.608: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 12:00:33.569: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@6m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 13:03:48.677: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@6m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 13:25:07.120: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 13:41:30.776: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 13:41:30.881: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 14:57:34.361: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 16:15:17.218: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@30s BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 16:58:30.348: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}] 08-19 19:16:10.025: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}] 08-19 19:17:45.559: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@1m9s BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}] 08-19 19:17:45.812: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}] 08-19 19:20:54.702: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@30s BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}] 08-19 19:20:57.410: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}] 08-19 19:29:04.001: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}] 08-19 19:32:26.711: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}] 08-19 19:33:43.534: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@1m11s BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}] 08-19 19:33:43.748: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}] 08-19 19:33:45.874: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@1m11s BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}] 08-19 19:33:45.905: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}] ```

In fact, without the manual restart, emission also stopped polling at around 16:58

shankari commented 2 years ago

Let's check out different these if we ignore all the restarts. Interestingly, they are identical except for the times when (I think) we manually restarted emission.

So is this what is going on? The various apps coordinate with each other and they basically stop checking location at some point. If it is before that point, all of them work. After, and none of them work.

Let's try to validate those assumptions against the other logs next...

shankari commented 2 years ago

I think that this is unlikely to be the case on my personal phone, since the geofence typically does exit after the trip is complete. But at least now we know which logs to look for. And even for these logs, we got the geofence exit after the trip is complete on the second trip to the library, so can check that out...

Second trip to the library

Arrived home at around 10:30am
Left again at around 10:55am
Arrived at library at around 11:05am

In fact, according to screenshots that I took geofence was detected between 11:01 and 11:04

Not detected at 11:01	Detected at 11:04

There are these big gaps in the checking and it looks like we checked right around 10:57 and then only at 11:07 (10 mins later). We did check a lot at around 11:19, but by that time the trip was over.

But then how did we detect the exited geofence at 11:04?

shankari commented 2 years ago

ok so we do have more logs in the dump taken right around that time

Looks like there is a location request at 10:57 for both e-mission and openpath The engine delivers a location at 10:57 and then at 11:02 (5 mins later) And then at least the openpath request gets converted to HIGH_ACCURACY

      08-19 10:57:10.103: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}]
      08-19 10:57:10.115: engine request = Request[@5m BALANCED_POWER_ACCURACY, WorkSource{10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}]
      08-19 10:57:10.115: delivered location[1] to 10190/com.google.android.gms[geofencer_provider]/cf09a050
      08-19 10:57:10.126: received LocationAvailability[true]
      08-19 10:57:11.279: received WIFI location[1]
      08-19 10:57:11.280: delivered location[1] to 10190/com.google.android.gms[awareness_provider]/49ef3cae
      08-19 10:57:11.286: delivered location[1] to 10190/com.google.android.gms[geofencer_provider]/cf09a050
      08-19 10:57:11.288: delivered location[1] to 10190/com.google.android.gms[fused_provider_shim]/3e7f8e47
      08-19 10:57:11.291: received LocationAvailability[true]
      08-19 11:02:11.677: received WIFI location[1]
      08-19 11:02:11.678: delivered location[1] to 10190/com.google.android.gms[awareness_provider]/49ef3cae
      08-19 11:02:11.683: delivered location[1] to 10190/com.google.android.gms[geofencer_provider]/cf09a050
      08-19 11:02:11.686: delivered location[1] to 10190/com.google.android.gms[fused_provider_shim]/3e7f8e47
      08-19 11:02:11.774: +client 10320/gov.nrel.cims.openpath/ddea5c0 -> Request[@30s HIGH_ACCURACY, minUpdateInterval=5s, waitForAccurateLocation, WorkSource{10320 gov.nrel.cim
s.openpath}]
      08-19 11:02:11.789: delivered location[1] to 10320/gov.nrel.cims.openpath/ddea5c0
      08-19 11:02:11.799: engine request = Request[@30s HIGH_ACCURACY, WorkSource{10320 gov.nrel.cims.openpath}]
      08-19 11:02:11.801: -client 10190/com.google.android.gms[geofencer_provider]/cf09a050

shankari commented 2 years ago

And here's something that captures that moment in the geofencer state machine as well (I only wish it had captured the moment the geofence exit was triggered).

    GeofencerStateMachine:
     total records=321
     rec[0]: time=08-19 11:02:07.104 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_SYSTEM_EVENT_CMD
     rec[1]: time=08-19 11:02:11.702 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_LOCATION_CMD
     rec[2]: time=08-19 11:02:11.771 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_REMOVE_GEOFENCE_CMD
     rec[3]: time=08-19 11:02:11.773 processed=WalkingActivityState org=WalkingActivityState dest=NoGeofenceState what=SM_REGISTERED_GEOFENCES_CHANGED_CMD
     rec[4]: time=08-19 11:02:11.778 processed=NoGeofenceState org=NoGeofenceState dest=<null> what=SM_SAVE_ACTIVITY_STATE_CMD
     rec[5]: time=08-19 11:02:11.840 processed=NoGeofenceState org=NoGeofenceState dest=<null> what=SM_REMOVE_GEOFENCE_CMD
     rec[6]: time=08-19 11:02:47.927 processed=<null> org=NoGeofenceState dest=<null> what=SM_WIFI_CONNECTIVITY_CHANGED
     rec[7]: time=08-19 11:03:51.073 processed=NoGeofenceState org=NoGeofenceState dest=<null> what=SM_SYSTEM_EVENT_CMD
     rec[8]: time=08-19 11:04:41.446 processed=NoGeofenceState org=NoGeofenceState dest=<null> what=SM_SYSTEM_EVENT_CMD
     rec[9]: time=08-19 11:06:20.289 processed=<null> org=NoGeofenceState dest=<null> what=SM_WIFI_CONNECTIVITY_CHANGED
    curState=NoGeofenceState

So far, this seems pretty expected. The geofence code checks for location every 5 minutes. Note that this is not consistent with our setting for the responsiveness. We set it to 5 * 1000 milliseconds = 5 seconds.

Sets the best-effort notification responsiveness of the geofence. Defaults to 0. Setting a big responsiveness value, for example 5 minutes, can save power significantly. However, setting a very small responsiveness value, for example 5 seconds, doesn't necessarily mean you will get notified right after the user enters or exits a geofence: internally, the geofence might adjust the responsiveness value to save power when needed.

So we might want to dial that up to something closer to a minute ([@5m BALANCED_POWER_ACCURACY) to see if android will at least honor it in that case.

And it so happens that we check at 10:57, just when the trip started, and then at 11:02, almost when the trip ended. However, this doesn't explain why we are missing even longer trips like to/from karate.

Note also that although we have turned on significant motion and activity transitions, the significant motion check is still disabled for the geofence

      GeofencerDeviceCapabilities:
        gps: supported(true), enabled(true)
        nlp: supported(true), enabled(true)
        significant_motion_detector: supported(true), enabled(false)
        gps_hardware_geofencing: supported(true), enabled(false)
        chre_geofencing: supported(true), enabled(false)

and also in the one later in the evening when could see the transitions on the phone

      GeofencerDeviceCapabilities:
        gps: supported(true), enabled(true)
        nlp: supported(true), enabled(true)
        significant_motion_detector: supported(true), enabled(false)
        gps_hardware_geofencing: supported(true), enabled(false)
        chre_geofencing: supported(true), enabled(false)

shankari commented 2 years ago

Looking to dig deeper into the "save power when needed" option, since it looks like all power options are dialed down, I found https://support.google.com/pixelphone/answer/7015477?hl=en

Double-checked on my personal phone and the apps are optimized. That might also explain how right after an install/update, the apps work better than over the long term.

Will try to turn off optimization on the Pixel today and see if that helps. This could also explain how/why the app worked properly when it was plugged in. Still don't understand why the geofence did not trigger even after 15-20 mins (e.g. on trip to karate), but now we can figure it out!

Note also that since Android 8,

Geofencing responsiveness changes from tens of seconds to approximately two minutes. This change noticeably improves battery performance—up to 10 times better on some devices.

What I don't understand is why this changed suddenly around the end of July, but hopefully the myriad logs that I have will help debug.

shankari commented 2 years ago

Current status:

emission: optimized with activity transitions turned on
NREL OpenPATH: unoptimized
CanBikeCO: optimized, stock
Ma Mobilite: not turning tracking off and on

shankari commented 2 years ago

While going to the store yesterday, we took the dump at

== dumpstate: 2022-08-19 19:23:13

The geofence exit (only on e-mission) was at

  #146: act=local.transition.exited_geofence flg=0x10 pkg=edu.berkeley.eecs.emission
    0 dispatch +64ms finish
    enq=2022-08-19 19:20:57.445 disp=2022-08-19 19:20:57.445 fin=2022-08-19 19:20:57.509

It does look like generating the geofence transition requires multiple partial wake locks

Wake Lock Log

``` 08-19 19:20:57.348 - 10190 - ACQ NlpWakeLock (partial) 08-19 19:20:57.355 - 10190 - ACQ NlpWakeLock (partial) 08-19 19:20:57.362 - 10190 - REL NlpWakeLock 08-19 19:20:57.363 - 10190 - ACQ NlpWakeLock (partial) 08-19 19:20:57.368 - 10190 - REL NlpWakeLock 08-19 19:20:57.370 - 10190 - ACQ NlpWakeLock (partial) 08-19 19:20:57.374 - 10190 - REL NlpWakeLock 08-19 19:20:57.375 - 10190 - ACQ GCoreFlp (partial) 08-19 19:20:57.376 - 10190 - REL GCoreFlp 08-19 19:20:57.376 - 10190 - ACQ GCoreFlp (partial) 08-19 19:20:57.376 - 10190 - REL NlpWakeLock 08-19 19:20:57.378 - 10190 - REL NlpWakeLock 08-19 19:20:57.379 - 10190 - ACQ CMWakeLock (partial) 08-19 19:20:57.380 - 10190 - ACQ FusedLocation (partial) 08-19 19:20:57.381 - 10190 - REL CMWakeLock 08-19 19:20:57.384 - 10190 - REL FusedLocation 08-19 19:20:57.385 - 10190 - ACQ Wakeful StateMachine: GeofencerStateMachine (partial) 08-19 19:20:57.388 - 10190 - REL GCoreFlp 08-19 19:20:57.401 - 10190 - ACQ GeofencePendingIntentWakeLock (partial) 08-19 19:20:57.407 - 10190 - REL GeofencePendingIntentWakeLock 08-19 19:20:57.407 - 10190 - ACQ GeofencePendingIntentWakeLock (partial) 08-19 19:20:57.408 - 10190 - REL GeofencePendingIntentWakeLock 08-19 19:20:57.410 - 10190 - REL Wakeful StateMachine: GeofencerStateMachine 08-19 19:20:57.415 - 10190 - ACQ FusedLocation (partial) 08-19 19:20:57.420 - 10190 - REL FusedLocation 08-19 19:20:57.421 - 10190 - ACQ Wakeful StateMachine: GeofencerStateMachine (partial) 08-19 19:20:57.425 - 10190 - REL Wakeful StateMachine: GeofencerStateMachine 08-19 19:20:57.429 - 10190 - ACQ NlpWakeLock (partial) 08-19 19:20:57.433 - 10190 - REL NlpWakeLock 08-19 19:20:57.434 - 10190 - ACQ NlpWakeLock (partial) 08-19 19:20:57.434 - 10190 - ACQ GCoreFlp (partial) 08-19 19:20:57.435 - 10190 - ACQ GCoreFlp (partial) 08-19 19:20:57.439 - 10190 - REL GCoreFlp 08-19 19:20:57.439 - 10190 - ACQ NlpWakeLock (partial) 08-19 19:20:57.440 - 10190 - ACQ Wakeful StateMachine: GeofencerStateMachine (partial) 08-19 19:20:57.440 - 10190 - REL GCoreFlp 08-19 19:20:57.440 - 10190 - REL Wakeful StateMachine: GeofencerStateMachine 08-19 19:20:57.442 - 10190 - REL NlpWakeLock 08-19 19:20:57.446 - 10190 - ACQ GCoreFlp (partial) 08-19 19:20:57.448 - 10190 - ACQ NlpWakeLock (partial) 08-19 19:20:57.451 - 10190 - REL NlpWakeLock 08-19 19:20:57.452 - 10190 - REL NlpWakeLock 08-19 19:20:57.554 - 10190 - ACQ Wakeful StateMachine: GeofencerStateMachine (partial) 08-19 19:20:57.565 - 10190 - REL Wakeful StateMachine: GeofencerStateMachine 08-19 19:20:57.568 - 10190 - ACQ FusedLocation (partial) 08-19 19:20:57.569 - 10190 - ACQ NlpWakeLock (partial) 08-19 19:20:57.571 - 10190 - REL NlpWakeLock 08-19 19:20:57.573 - 10190 - REL FusedLocation ```

Then, we requested location at 19:20:54, but got it at 19:20:57 (5 secs later). This is consistent with our geofence responsiveness. And is faster than the requested 30 secs.

08-19 19:20:54.702: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@30s BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}]
08-19 19:20:54.703: engine request = Request[@30s BALANCED_POWER_ACCURACY, WorkSource{10291 edu.berkeley.eecs.emission}]
08-19 19:20:57.377: received WIFI location[1]
08-19 19:20:57.378: delivered location[1] to 10190/com.google.android.gms[awareness_provider]/49ef3cae
08-19 19:20:57.385: delivered location[1] to 10190/com.google.android.gms[geofencer_provider]/cf09a050
08-19 19:20:57.386: delivered location[1] to 10190/com.google.android.gms[fused_provider_shim]/3e7f8e47
08-19 19:20:57.410: -client 10190/com.google.android.gms[geofencer_provider]/cf09a050

Then we request with 5m, but get the location almost immediately (within milliseconds).

08-19 19:20:57.410: +client 10190/com.google.android.gms[geofencer_provider]/cf09a050 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}]
08-19 19:20:57.421: engine request = Request[@5m BALANCED_POWER_ACCURACY, WorkSource{10291 edu.berkeley.eecs.emission}]
08-19 19:20:57.421: delivered location[1] to 10190/com.google.android.gms[geofencer_provider]/cf09a050
08-19 19:20:57.434: received LocationAvailability[true]
08-19 19:20:57.560: -client 10190/com.google.android.gms[geofencer_provider]/cf09a050

Then we bump up the accuracy to HIGH as part of ongoing tracking. Note that right after the request from emission, we get a request from fused location, and the locations are delivered to both. The initial locations come more frequently than 30 secs (~ 1 sec) and are not delivered to e-mission until 30 secs have passed. Later locations come in only every 30 secs and are always delivered to e-mission

``` 08-19 19:20:57.563: +client 10291/edu.berkeley.eecs.emission/31a4b621 -> Request[@30s HIGH_ACCURACY, minUpdateInterval=5s, waitForAccurateLocation, WorkSource{10291 edu.berkeley.eecs.emission}] 08-19 19:20:57.571: delivered location[1] to 10291/edu.berkeley.eecs.emission/31a4b621 08-19 19:20:57.572: engine request = Request[@30s HIGH_ACCURACY, WorkSource{10291 edu.berkeley.eecs.emission}] 08-19 19:20:57.594: received LocationAvailability[true] 08-19 19:20:57.607: received LocationAvailability[true] 08-19 19:20:57.620: +client 10190/com.google.android.gms[fused_location_provider]/47e73429 -> Request[PASSIVE, minUpdateInterval=750ms, maxCachedUpdateAge=1h, THROTTLE_NEVER, WorkSource{10190 com.google.android.gms}] 08-19 19:20:57.631: delivered location[1] to 10190/com.google.android.gms[fused_location_provider]/47e73429 08-19 19:20:57.900: received GPS location[1] 08-19 19:20:57.905: delivered location[1] to 10291/edu.berkeley.eecs.emission/31a4b621 08-19 19:20:57.905: delivered location[1] to 10190/com.google.android.gms[fused_location_provider]/47e73429 08-19 19:20:57.906: delivered location[1] to 10190/com.google.android.gms[awareness_provider]/49ef3cae 08-19 19:20:57.906: delivered location[1] to 10190/com.google.android.gms[fused_provider_shim]/3e7f8e47 08-19 19:20:57.907: received LocationAvailability[true] 08-19 19:20:58.202: received GPS location[1] 08-19 19:20:58.203: delivered location[1] to 10190/com.google.android.gms[fused_location_provider]/47e73429 08-19 19:20:58.204: delivered location[1] to 10190/com.google.android.gms[awareness_provider]/49ef3cae 08-19 19:20:58.204: delivered location[1] to 10190/com.google.android.gms[fused_provider_shim]/3e7f8e47 08-19 19:20:58.913: received GPS location[1] 08-19 19:20:58.915: delivered location[1] to 10190/com.google.android.gms[fused_location_provider]/47e73429 08-19 19:20:58.915: delivered location[1] to 10190/com.google.android.gms[awareness_provider]/49ef3cae 08-19 19:20:59.237: received WIFI location[1] 08-19 19:20:59.238: delivered location[1] to 10190/com.google.android.gms[fused_location_provider]/47e73429 08-19 19:20:59.239: delivered location[1] to 10190/com.google.android.gms[awareness_provider]/49ef3cae 08-19 19:20:59.239: delivered location[1] to 10190/com.google.android.gms[fused_provider_shim]/3e7f8e47 08-19 19:21:01.143: -client 10190/com.google.android.gms[earthquake_alerting]/661a96d 08-19 19:21:29.188: received GPS location[1] 08-19 19:21:29.192: delivered location[1] to 10291/edu.berkeley.eecs.emission/31a4b621 08-19 19:21:29.194: delivered location[1] to 10190/com.google.android.gms[fused_location_provider]/47e73429 08-19 19:21:29.194: delivered location[1] to 10190/com.google.android.gms[awareness_provider]/49ef3cae 08-19 19:21:29.194: delivered location[1] to 10190/com.google.android.gms[fused_provider_shim]/3e7f8e47 08-19 19:22:00.180: received GPS location[1] 08-19 19:22:00.185: delivered location[1] to 10291/edu.berkeley.eecs.emission/31a4b621 08-19 19:22:00.186: delivered location[1] to 10190/com.google.android.gms[fused_location_provider]/47e73429 08-19 19:22:00.187: delivered location[1] to 10190/com.google.android.gms[awareness_provider]/49ef3cae 08-19 19:22:00.187: delivered location[1] to 10190/com.google.android.gms[fused_provider_shim]/3e7f8e47 08-19 19:22:07.966: received GPS location[1] 08-19 19:22:07.973: delivered location[1] to 10291/edu.berkeley.eecs.emission/31a4b621 08-19 19:22:07.974: delivered location[1] to 10190/com.google.android.gms[fused_location_provider]/47e73429 08-19 19:22:07.976: delivered location[1] to 10190/com.google.android.gms[awareness_provider]/49ef3cae 08-19 19:22:07.977: delivered location[1] to 10190/com.google.android.gms[fused_provider_shim]/3e7f8e47 08-19 19:22:30.186: received GPS location[1] 08-19 19:22:30.196: delivered location[1] to 10291/edu.berkeley.eecs.emission/31a4b621 08-19 19:22:30.198: delivered location[1] to 10190/com.google.android.gms[fused_location_provider]/47e73429 08-19 19:22:30.199: delivered location[1] to 10190/com.google.android.gms[awareness_provider]/49ef3cae 08-19 19:22:30.199: delivered location[1] to 10190/com.google.android.gms[fused_provider_shim]/3e7f8e47 08-19 19:22:42.631: received GPS location[1] 08-19 19:22:42.636: delivered location[1] to 10291/edu.berkeley.eecs.emission/31a4b621 08-19 19:22:42.637: delivered location[1] to 10190/com.google.android.gms[fused_location_provider]/47e73429 08-19 19:22:42.638: delivered location[1] to 10190/com.google.android.gms[awareness_provider]/49ef3cae 08-19 19:22:42.638: delivered location[1] to 10190/com.google.android.gms[fused_provider_shim]/3e7f8e47 08-19 19:23:01.178: received GPS location[1] 08-19 19:23:01.190: delivered location[1] to 10291/edu.berkeley.eecs.emission/31a4b621 08-19 19:23:01.191: delivered location[1] to 10190/com.google.android.gms[fused_location_provider]/47e73429 08-19 19:23:01.191: delivered location[1] to 10190/com.google.android.gms[awareness_provider]/49ef3cae 08-19 19:23:01.191: delivered location[1] to 10190/com.google.android.gms[fused_provider_shim]/3e7f8e47 08-19 19:23:17.428: received GPS location[1] 08-19 19:23:17.433: delivered location[1] to 10291/edu.berkeley.eecs.emission/31a4b621 08-19 19:23:17.434: delivered location[1] to 10190/com.google.android.gms[fused_location_provider]/47e73429 08-19 19:23:17.435: delivered location[1] to 10190/com.google.android.gms[awareness_provider]/49ef3cae 08-19 19:23:17.435: delivered location[1] to 10190/com.google.android.gms[fused_provider_shim]/3e7f8e47 08-19 19:23:31.177: received GPS location[1] 08-19 19:23:31.183: delivered location[1] to 10291/edu.berkeley.eecs.emission/31a4b621 08-19 19:23:31.184: delivered location[1] to 10190/com.google.android.gms[fused_location_provider]/47e73429 08-19 19:23:31.185: delivered location[1] to 10190/com.google.android.gms[awareness_provider]/49ef3cae 08-19 19:23:31.185: delivered location[1] to 10190/com.google.android.gms[fused_provider_shim]/3e7f8e47 08-19 19:23:52.214: received GPS location[1] 08-19 19:23:52.221: delivered location[1] to 10291/edu.berkeley.eecs.emission/31a4b621 08-19 19:23:52.222: delivered location[1] to 10190/com.google.android.gms[fused_location_provider]/47e73429 08-19 19:23:52.223: delivered location[1] to 10190/com.google.android.gms[awareness_provider]/49ef3cae 08-19 19:23:52.223: delivered location[1] to 10190/com.google.android.gms[fused_provider_shim]/3e7f8e47 08-19 19:24:01.191: received GPS location[1] 08-19 19:24:01.202: delivered location[1] to 10291/edu.berkeley.eecs.emission/31a4b621 08-19 19:24:01.204: delivered location[1] to 10190/com.google.android.gms[fused_location_provider]/47e73429 08-19 19:24:01.206: delivered location[1] to 10190/com.google.android.gms[awareness_provider]/49ef3cae 08-19 19:24:01.206: delivered location[1] to 10190/com.google.android.gms[fused_provider_shim]/3e7f8e47 08-19 19:24:26.431: received GPS location[1] 08-19 19:24:26.433: delivered location[1] to 10291/edu.berkeley.eecs.emission/31a4b621 08-19 19:24:26.434: delivered location[1] to 10190/com.google.android.gms[fused_location_provider]/47e73429 08-19 19:24:26.434: delivered location[1] to 10190/com.google.android.gms[awareness_provider]/49ef3cae 08-19 19:24:26.434: delivered location[1] to 10190/com.google.android.gms[fused_provider_shim]/3e7f8e47 08-19 19:24:31.191: received GPS location[1] 08-19 19:24:31.210: delivered location[1] to 10291/edu.berkeley.eecs.emission/31a4b621 08-19 19:24:31.211: delivered location[1] to 10190/com.google.android.gms[fused_location_provider]/47e73429 08-19 19:24:31.211: delivered location[1] to 10190/com.google.android.gms[awareness_provider]/49ef3cae 08-19 19:24:31.211: delivered location[1] to 10190/com.google.android.gms[fused_provider_shim]/3e7f8e47 08-19 19:25:01.186: received GPS location[1] 08-19 19:25:01.194: delivered location[1] to 10291/edu.berkeley.eecs.emission/31a4b621 08-19 19:25:01.195: delivered location[1] to 10190/com.google.android.gms[fused_location_provider]/47e73429 08-19 19:25:01.197: delivered location[1] to 10190/com.google.android.gms[awareness_provider]/49ef3cae 08-19 19:25:01.197: delivered location[1] to 10190/com.google.android.gms[fused_provider_shim]/3e7f8e47 ```

And this time, we do actually overlap the geofence exit

``` GeofencerStateMachine: total records=965 rec[0]: time=08-19 19:20:57.408 processed=WalkingActivityState org=WalkingActivityState dest= what=SM_LOCATION_CMD rec[1]: time=08-19 19:20:57.425 processed=WalkingActivityState org=WalkingActivityState dest= what=SM_LOCATION_CMD rec[2]: time=08-19 19:20:57.440 processed=WalkingActivityState org=WalkingActivityState dest= what=SM_LOCATION_AVAILABILITY_CHANGED rec[3]: time=08-19 19:20:57.559 processed=WalkingActivityState org=WalkingActivityState dest= what=SM_REMOVE_GEOFENCE_CMD rec[4]: time=08-19 19:20:57.560 processed=WalkingActivityState org=WalkingActivityState dest=NoGeofenceState what=SM_REGISTERED_GEOFENCES_CHANGED_CMD rec[5]: time=08-19 19:20:57.565 processed=NoGeofenceState org=NoGeofenceState dest= what=SM_SAVE_ACTIVITY_STATE_CMD rec[6]: time=08-19 19:21:01.088 processed= org=NoGeofenceState dest= what=SM_WIFI_CONNECTIVITY_CHANGED rec[7]: time=08-19 19:21:02.556 processed=NoGeofenceState org=NoGeofenceState dest= what=SM_SYSTEM_EVENT_CMD rec[8]: time=08-19 19:23:20.308 processed=NoGeofenceState org=NoGeofenceState dest= what=SM_SYSTEM_EVENT_CMD rec[9]: time=08-19 19:24:15.298 processed=NoGeofenceState org=NoGeofenceState dest= what=SM_SYSTEM_EVENT_CMD curState=NoGeofenceState LogRecords: capacity=200 ```

Consider the overlap here

08-19 19:20:57.385: delivered location[1] to 10190/com.google.android.gms[geofencer_provider]/cf09a050
     rec[0]: time=08-19 19:20:57.408 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_LOCATION_CMD

08-19 19:20:57.421: delivered location[1] to 10190/com.google.android.gms[geofencer_provider]/cf09a050
     rec[1]: time=08-19 19:20:57.425 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_LOCATION_CMD

08-19 19:20:57.434: received LocationAvailability[true]
     rec[2]: time=08-19 19:20:57.440 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_LOCATION_AVAILABILITY_CHANGED

  #146: act=local.transition.exited_geofence flg=0x10 pkg=edu.berkeley.eecs.emission enq=2022-08-19 19:20:57.445 disp=2022-08-19 19:20:57.445 fin=2022-08-19 19:20:57.509
     rec[3]: time=08-19 19:20:57.559 processed=WalkingActivityState org=WalkingActivityState dest=<null> what=SM_REMOVE_GEOFENCE_CMD

Nothing relevant in the system logs around this time

--------- beginning of system

08-19 19:20:57.106  1000  1858  1858 W NotificationHistory: Attempted to add notif for locked/gone/disabled user 0
08-19 19:20:57.115  1000  1858  2325 W UserManagerService: Cannot retrieve activities for disabled profile -1 from 0
08-19 19:20:57.536  1000  1858  3836 W ProcessStats: Tracking association SourceState{b60bc98 system/1000 BTopFgs #362322} whose proc state 2 is better than process ProcessState{d3fbc9d com.google.android.gms.persistent/10190 pkg=com.google.android.gms} proc state 3 (19 skipped)
08-19 19:20:57.589  1000  1858  3836 W AppOps  : Noting op not finished: uid 10190 pkg com.google.android.gms code 113 startTime of in progress event=1660962057535
08-19 19:20:57.595  1000  1858  3600 W AppOps  : Noting op not finished: uid 10190 pkg com.google.android.gms code 113 startTime of in progress event=1660962057535
08-19 19:20:57.607  1000  1858  3600 W AppOps  : Noting op not finished: uid 10291 pkg edu.berkeley.eecs.emission code 79 startTime of in progress event=1660961510063

Main logs is already from 19:20:58 so still doesn't include the logs from the geofence exit. Don't think we are ever going to be able to use main logs because we are not going to be able to take the bug report quickly enough

--------- beginning of main
08-19 19:20:58.784   gps  1428 24230 D LOWI-8.6.0.75: [LOWI-Scan] BSS 6a:80:88:30:7f:8a LOWI_PHY_MODE_11AC_VHT80(10), Beacon Interval: 100, LOWI_ENCRYPTION_TYPE_WPA_PSK 11mcRanging: No, ANQP: No, LCI: No, Civic: No, capability(0x1111): ESS Privacy SpectrumMgmt

Let's see if there's anything interesting in the logcat. Nope. This is it.

Now let's go back to the older logs for missing trips.

shankari commented 2 years ago

Checking trip to Stanford last Sunday (https://github.com/e-mission/e-mission-docs/issues/774#issuecomment-1214599652)

This seems to be a combination of (1) basically not getting any location along with (2) very intermittent geofence checks, which are probably related to (1).

personal phone

This is when the geofence exit was detected

  #192: act=local.transition.exited_geofence flg=0x10 pkg=gov.nrel.cims.openpath
    +47ms dispatch +35ms finish
    enq=2022-08-14 15:38:20.296 disp=2022-08-14 15:38:20.343 fin=2022-08-14 15:38:20.378

We checked the geofence location at 15:23, 15:25, 15:25 and then a big gap to 15:38 which is what resulted in the straight line from home to the train station. And fairly soon after that 15:38, we detect the geofence exit and start high accuracy tracking

      08-14 15:23:12.331: +client 10189/com.google.android.gms[.location_base]/a69f37a7 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10279 gov.colorado.energyoffice.emission, 10298 gov.nrel.cims.openpath}]
      08-14 15:25:51.942: +client 10189/com.google.android.gms[.location_base]/a69f37a7 -> Request[@1m11s BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10279 gov.colorado.energyoffice.emission, 10298 gov.nrel.cims.openpath}]
      08-14 15:25:54.070: +client 10189/com.google.android.gms[.location_base]/a69f37a7 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10279 gov.colorado.energyoffice.emission, 10298 gov.nrel.cims.openpath}]

      08-14 15:38:19.830: +client 10189/com.google.android.gms[.location_base]/a69f37a7 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10279 gov.colorado.energyoffice.emission, 10298 gov.nrel.cims.openpath}]
      08-14 15:38:20.165: +client 10189/com.google.android.gms[.location_base]/a69f37a7 -> Request[@9m9s BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10279 gov.colorado.energyoffice.emission, 10298 gov.nrel.cims.openpath}]
      08-14 15:38:20.392: +client 10279/gov.colorado.energyoffice.emission/d1c2e900 -> Request[@30s HIGH_ACCURACY, minUpdateInterval=5s, waitForAccurateLocation, WorkSource{10279 gov.colorado.energyoffice.emission}]
      08-14 15:38:20.405: engine request = Request[@30s HIGH_ACCURACY, WorkSource{10279 gov.colorado.energyoffice.emission}]

      08-14 15:38:20.444: +client 10298/gov.nrel.cims.openpath/e052c881 -> Request[@30s HIGH_ACCURACY, minUpdateInterval=5s, waitForAccurateLocation, WorkSource{10298 gov.nrel.cims.openpath}]
      08-14 15:38:20.462: engine request = Request[@30s HIGH_ACCURACY, WorkSource{10279 gov.colorado.energyoffice.emission, 10298 gov.nrel.cims.openpath}]

pixel phone

so we actually got a geofence exit around 15:32 and started high accuracy tracking

      08-14 15:25:51.617: +client 10190/com.google.android.gms[geofencer_provider]/b4d75ed -> Request[@1m9s BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10268 gov.colorado.energyoffice.emission, 10281 com.fabmoqc.mamobilite, 10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}]
      08-14 15:25:52.974: +client 10190/com.google.android.gms[geofencer_provider]/b4d75ed -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10268 gov.colorado.energyoffice.emission, 10281 com.fabmoqc.mamobilite, 10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}]
      08-14 15:32:20.551: +client 10190/com.google.android.gms[geofencer_provider]/b4d75ed -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10268 gov.colorado.energyoffice.emission, 10281 com.fabmoqc.mamobilite, 10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}]

      08-14 15:32:20.666: +client 10281/com.fabmoqc.mamobilite/af455f61 -> Request[@30s HIGH_ACCURACY, minUpdateInterval=5s, waitForAccurateLocation, WorkSource{10281 com.fabmoqc.mamobilite}]
      08-14 15:32:20.737: +client 10291/edu.berkeley.eecs.emission/f6df5bf2 -> Request[@30s HIGH_ACCURACY, minUpdateInterval=5s, waitForAccurateLocation, WorkSource{10291 edu.berkeley.eecs.emission}]
      08-14 15:32:20.763: +client 10320/gov.nrel.cims.openpath/3f3e2e7 -> Request[@30s HIGH_ACCURACY, minUpdateInterval=5s, waitForAccurateLocation, WorkSource{10320 gov.nrel.cims.openpath}]

And then around 15:37, we stop the tracking and recreate a geofence, maybe while we were waiting in the train...

      08-14 15:37:28.388: +client 10190/com.google.android.gms[geofencer_provider]/b4d75ed -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10268 gov.colorado.energyoffice.emission, 10320 gov.nrel.cims.openpath}]

And then the geofence never exited. We also have a giant gap between 16:04 and 17:23 and then to 18:11, when the geofence finally exited and was then reinstated at around 18:16 (5 mins later) as expected.

      08-14 15:37:28.533: +client 10190/com.google.android.gms[geofencer_provider]/b4d75ed -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10268 gov.colorado.energyoffice.emission, 10281 com.fabmoqc.mamobilite, 10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}]
      08-14 15:52:08.503: +client 10190/com.google.android.gms[geofencer_provider]/b4d75ed -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10268 gov.colorado.energyoffice.emission, 10281 com.fabmoqc.mamobilite, 10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}]
      08-14 16:04:37.069: +client 10190/com.google.android.gms[geofencer_provider]/b4d75ed -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10268 gov.colorado.energyoffice.emission, 10281 com.fabmoqc.mamobilite, 10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}]

      08-14 17:23:02.555: +client 10190/com.google.android.gms[geofencer_provider]/b4d75ed -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10268 gov.colorado.energyoffice.emission, 10281 com.fabmoqc.mamobilite, 10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}]
      08-14 17:34:45.155: +client 10190/com.google.android.gms[geofencer_provider]/b4d75ed -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10268 gov.colorado.energyoffice.emission, 10281 com.fabmoqc.mamobilite, 10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}]
      08-14 17:35:21.558: +client 10190/com.google.android.gms[geofencer_provider]/b4d75ed -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10268 gov.colorado.energyoffice.emission, 10281 com.fabmoqc.mamobilite, 10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}]

      08-14 18:11:58.201: +client 10190/com.google.android.gms[geofencer_provider]/b4d75ed -> Request[@18m46s BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10268 gov.colorado.energyoffice.emission, 10281 com.fabmoqc.mamobilite, 10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}]
      08-14 18:11:58.248: +client 10281/com.fabmoqc.mamobilite/bda0374 -> Request[@30s HIGH_ACCURACY, minUpdateInterval=5s, waitForAccurateLocation, WorkSource{10281 com.fabmoqc.mamobilite}]
      08-14 18:11:58.340: +client 10291/edu.berkeley.eecs.emission/cd8d60e1 -> Request[@30s HIGH_ACCURACY, minUpdateInterval=5s, waitForAccurateLocation, WorkSource{10291 edu.berkeley.eecs.emission}]

      08-14 18:16:56.447: +client 10190/com.google.android.gms[geofencer_provider]/b4d75ed -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10320 gov.nrel.cims.openpath}]

Interestingly, after a few more checks, we again start a high accuracy sensing regime

      08-14 18:16:56.529: +client 10190/com.google.android.gms[geofencer_provider]/b4d75ed -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10281 com.fabmoqc.mamobilite, 10320 gov.nrel.cims.openpath}]
      08-14 18:16:56.587: +client 10190/com.google.android.gms[geofencer_provider]/b4d75ed -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10268 gov.colorado.energyoffice.emission, 10281 com.fabmoqc.mamobilite, 10320 gov.nrel.cims.openpath}]
      08-14 18:16:56.735: +client 10190/com.google.android.gms[geofencer_provider]/b4d75ed -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10268 gov.colorado.energyoffice.emission, 10281 com.fabmoqc.mamobilite, 10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}]
      08-14 18:41:21.396: +client 10190/com.google.android.gms[geofencer_provider]/b4d75ed -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10268 gov.colorado.energyoffice.emission, 10281 com.fabmoqc.mamobilite, 10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}]

      08-14 18:43:26.753: engine request = Request[@30s HIGH_ACCURACY, WorkSource{10268 gov.colorado.energyoffice.emission, 10281 com.fabmoqc.mamobilite, 10291 edu.berkeley.eecs.emission, 10320 gov.nrel.cims.openpath}]

and that is when we start actually getting locations

``` 08-14 18:43:48.877: delivered location[1] to 10268/gov.colorado.energyoffice.emission/99723179 08-14 18:43:48.883: delivered location[1] to 10281/com.fabmoqc.mamobilite/d4bb8a90 08-14 18:43:48.890: delivered location[1] to 10320/gov.nrel.cims.openpath/18a39ebe 08-14 18:43:48.898: delivered location[1] to 10291/edu.berkeley.eecs.emission/276c7fa7 08-14 18:43:48.899: delivered location[1] to 10190/com.google.android.gms[fused_location_provider]/f6231643 08-14 18:43:48.899: delivered location[1] to 10190/com.google.android.gms[fused_provider_shim]/24bcd0b9 08-14 18:43:48.901: received LocationAvailability[true] 08-14 18:43:55.126: received WIFI location[1] 08-14 18:43:55.128: delivered location[1] to 10190/com.google.android.gms[awareness_provider]/7d26e08b 08-14 18:43:55.134: delivered location[1] to 10268/gov.colorado.energyoffice.emission/99723179 08-14 18:43:55.139: delivered location[1] to 10281/com.fabmoqc.mamobilite/d4bb8a90 08-14 18:43:55.145: delivered location[1] to 10320/gov.nrel.cims.openpath/18a39ebe 08-14 18:43:55.149: delivered location[1] to 10291/edu.berkeley.eecs.emission/276c7fa7 08-14 18:43:55.150: delivered location[1] to 10190/com.google.android.gms[fused_location_provider]/f6231643 08-14 18:43:55.150: delivered location[1] to 10190/com.google.android.gms[fused_provider_shim]/24bcd0b9 08-14 18:43:57.158: engine request = Request[@30s HIGH_ACCURACY, WorkSource{10268 gov.colorado.energyoffice.emission, 10281 com.fabmoqc.mamobilite, 10291 edu.berkeley.eecs.emission}] 08-14 18:43:57.361: received LocationAvailability[true] 08-14 18:43:58.656: received WIFI location[1] 08-14 18:43:58.658: delivered location[1] to 10190/com.google.android.gms[awareness_provider]/7d26e08b 08-14 18:43:58.664: delivered location[1] to 10268/gov.colorado.energyoffice.emission/99723179 08-14 18:43:58.669: delivered location[1] to 10281/com.fabmoqc.mamobilite/d4bb8a90 08-14 18:43:58.674: delivered location[1] to 10320/gov.nrel.cims.openpath/18a39ebe 08-14 18:43:58.679: delivered location[1] to 10291/edu.berkeley.eecs.emission/276c7fa7 08-14 18:43:58.681: delivered location[1] to 10190/com.google.android.gms[fused_location_provider]/f6231643 08-14 18:43:58.681: delivered location[1] to 10190/com.google.android.gms[fused_provider_shim]/24bcd0b9 08-14 18:43:58.682: received LocationAvailability[true] 08-14 18:44:25.122: received GPS location[1] 08-14 18:44:25.124: delivered location[1] to 10190/com.google.android.gms[awareness_provider]/7d26e08b 08-14 18:44:25.129: delivered location[1] to 10268/gov.colorado.energyoffice.emission/99723179 08-14 18:44:25.132: delivered location[1] to 10281/com.fabmoqc.mamobilite/d4bb8a90 08-14 18:44:25.136: delivered location[1] to 10320/gov.nrel.cims.openpath/18a39ebe 08-14 18:44:25.139: delivered location[1] to 10291/edu.berkeley.eecs.emission/276c7fa7 08-14 18:44:25.140: delivered location[1] to 10190/com.google.android.gms[fused_location_provider]/f6231643 08-14 18:44:25.140: delivered location[1] to 10190/com.google.android.gms[fused_provider_shim]/24bcd0b9 ```

$ grep -r "delivered location" bugreport-flame-SQ3A.220705.003.A1-2022-08-14-18-45-59.txt | head -n 3
bugreport-flame-SQ3A.220705.003.A1-2022-08-14-18-45-59.txt:      08-14 18:43:48.877: delivered location[1] to 10268/gov.colorado.energyoffice.emission/99723179
bugreport-flame-SQ3A.220705.003.A1-2022-08-14-18-45-59.txt:      08-14 18:43:48.883: delivered location[1] to 10281/com.fabmoqc.mamobilite/d4bb8a90
bugreport-flame-SQ3A.220705.003.A1-2022-08-14-18-45-59.txt:      08-14 18:43:48.890: delivered location[1] to 10320/gov.nrel.cims.openpath/18a39ebe

$ grep -r "delivered location" bugreport-flame-SQ3A.220705.003.A1-2022-08-14-18-45-59.txt | tail -n 3
bugreport-flame-SQ3A.220705.003.A1-2022-08-14-18-45-59.txt:      08-14 18:46:48.936: delivered location[1] to 10190/com.google.android.gms[geofencer_provider]/b4d75ed
bugreport-flame-SQ3A.220705.003.A1-2022-08-14-18-45-59.txt:      08-14 18:46:48.941: delivered location[1] to 10320/gov.nrel.cims.openpath/18a39ebe
bugreport-flame-SQ3A.220705.003.A1-2022-08-14-18-45-59.txt:      08-14 18:46:48.942: delivered location[1] to 10190/com.google.android.gms[fused_provider_shim]/24bcd0b9

There are 309 entries

$ grep -r "background/location" ../pixel_locations_aug_14_stanford_trip | wc -l
     309

Including some at 15:xxx so we may not be recording every time a location is actually delivered in the bug report

            "fmt_time": "2022-08-14T15:36:58-07:00",
            "fmt_time": "2022-08-14T15:37:27-07:00",
            "fmt_time": "2022-08-14T18:11:58-07:00",

shankari commented 2 years ago

wrt https://github.com/e-mission/e-mission-docs/issues/774#issuecomment-1221367768 only NREL OpenPATH turned on during the trip there CanBikeCO was in the start state

none of them turned on during the trip back initially I then reset (I think) CanBikeCO Then only e-mission turned on

only openpath on trip there	on way back, first no apps	then only e-mission

shankari commented 2 years ago

Only e-mission had a geofence to begin with

      08-20 09:16:52.609: +client 10190/com.google.android.gms[geofencer_provider]/9fdc48c6 -> Request[@6m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}]
      08-20 09:58:07.434: +client 10190/com.google.android.gms[geofencer_provider]/9fdc48c6 -> Request[@6m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10268 gov.colorado.energyoffice.emission}]

Registered geofence for OpenPATH, but don't see similar poll for e-mission now

      08-20 11:34:29.162: +client 10190/com.google.android.gms[geofencer_provider]/9fdc48c6 -> Request[@6m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10320 gov.nrel.cims.openpath}]
      08-20 13:29:31.946: +client 10190/com.google.android.gms[geofencer_provider]/9fdc48c6 -> Request[@1m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10320 gov.nrel.cims.openpath}]
      08-20 13:29:32.029: +client 10190/com.google.android.gms[geofencer_provider]/9fdc48c6 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10320 gov.nrel.cims.openpath}]
      08-20 13:30:56.618: engine request = Request[@5m BALANCED_POWER_ACCURACY, WorkSource{10320 gov.nrel.cims.openpath}]

Then we got 1m but still BALANCED_POWER_ACCURACY

      08-20 13:31:00.515: +client 10190/com.google.android.gms[geofencer_provider]/9fdc48c6 -> Request[@1m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10320 gov.nrel.cims.openpath}]

Geofence exits, we start displaying "delivered location" logs 10 mins later, ~ 5 mins before we took the dump. emission et al are not even listening.

      08-20 13:31:00.644: +client 10320/gov.nrel.cims.openpath/13bdc867 -> Request[@30s HIGH_ACCURACY, minUpdateInterval=5s, waitForAccurateLocation, WorkSource{10320 gov.nrel.cims.openpath}]
      08-20 13:44:15.347: delivered location[1] to 10320/gov.nrel.cims.openpath/13bdc867
      08-20 13:44:15.348: delivered location[1] to 10190/com.google.android.gms[awareness_provider]/5039db15
      08-20 13:44:15.348: delivered location[1] to 10190/com.google.android.gms[fused_location_provider]/80903d96
      08-20 13:44:15.350: received LocationAvailability[true]
      08-20 13:44:34.319: received LocationAvailability[true]
      08-20 13:44:41.357: received GPS location[1]
      08-20 13:44:41.358: delivered location[1] to 10190/com.google.android.gms[fused_provider_shim]/fcbbfa4b
      08-20 13:44:41.368: delivered location[1] to 10320/gov.nrel.cims.openpath/13bdc867
      08-20 13:44:41.370: delivered location[1] to 10190/com.google.android.gms[awareness_provider]/5039db15
      08-20 13:44:41.370: delivered location[1] to 10190/com.google.android.gms[fused_location_provider]/80903d96
      08-20 13:44:41.372: received LocationAvailability[true]

No geofences are visible (openpath is in ongoing state, does not have geofence, other apps have apparently not created geofences correctly or geofences have been deleted).

    Geofencer State:
    Registered geofences:
        <none>SystemMemoryCache for com.google.android.location.internal.GoogleLocationManagerService
     type = 2
     id = 164c2c8a-58e8-4e50-9051-190698ff4f9c
     cacheData = []

    UniqueIds in use: 0
    Last location:
        Time=Sat Aug 20 13:30:56 PDT 2022
        Location[fused 37.388966,-122.087070 hAcc=70.972 et=+8d6h22m0s57ms alt=-2.5999999046325684 vAcc=1.4730011 vel=2.4009047 bear=247.74724 {Bundle[mParcelledData.dataSize=372]}]
    Dump of hardware geofencing:
        Class is RealBlockingGeofenceHardware, monitoringType=0, limit=50
        Supported=true, available=false, enabled on this device=true
        Registered geofences:
        <none>
    Location update interval=-1s
    Dump of ActivityDetector:
        Interval=-1s
    Dump of current state:
        NoGeofenceState
    GeofencerStateMachine:
     total records=441

And it looks pretty clear that geofences were not even created properly for (say) emission. Not sure if this is because we have a SIM card but no data plan. We should also check with geofence creation status in the emission log and then move on

        gov.colorado.energyoffice.emission: addGeofenceRequests: 2 removeGeofenceRequests: 1 geofenceEnters: 0 geofenceExits: 0 geofenceDwells: 0 geofenceCountMaximum: 1 transition/initial(2/2): 2
        gov.nrel.cims.openpath: addGeofenceRequests: 2 removeGeofenceRequests: 2 geofenceEnters: 0 geofenceExits: 1 geofenceDwells: 0 geofenceCountMaximum: 1 transition/initial(2/2): 2
        edu.berkeley.eecs.emission: addGeofenceRequests: 0 removeGeofenceRequests: 0 geofenceEnters: 0 geofenceExits: 0 geofenceDwells: 0 geofenceCountMaximum: 1 transition/initial(2/2): 1

shankari commented 2 years ago

For the record, (I don't want to jinx this, but since yesterday, logging is working perfectly on my personal phone).

shankari commented 2 years ago

wrt "We should also check with geofence creation status in the emission log and then move on"

Geofence was apparently created properly last night

31425,1660963283.674,2022-08-19T19:41:23.674000-07:00,"CreateGeofenceAction : Last location is Location[fused (my house) hAcc=12.271 et=+7d12h32m27s48ms alt=-4.799999713897705 vAcc=1.2283946 {Bundle[EMPTY_PARCEL]}] using it"
31426,1660963283.676,2022-08-19T19:41:23.676000-07:00,"CreateGeofenceAction : creating geofence at location Location[fused (my house) hAcc=12.271 et=+7d12h32m27s48ms alt=-4.799999713897705 vAcc=1.2283946 {Bundle[EMPTY_PARCEL]}]"

and then nothing I started and stopped a trip manually

33171,1661030318.96,2022-08-20T14:18:38.960000-07:00,TripDiaryStateMachineService : TripDiaryStateMachineReceiver handleTripStart(local.transition.exited_geofence) called
33222,1661030319.1379998,2022-08-20T14:18:39.138000-07:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.ongoing_trip"
33248,1661030321.1929998,2022-08-20T14:18:41.193000-07:00,"TripDiaryStateMachineService : handleAction(local.state.ongoing_trip, local.transition.stopped_moving) called"

33264,1661030321.2289999,2022-08-20T14:18:41.229000-07:00,"CreateGeofenceAction : Last location is Location[fused (stanford shopping center) hAcc=9.667 et=+8d7h9m22s604ms alt=-8.642381725305299 vAcc=27.64749 vel=1.2806634 sAcc=0.2408319 bear=201.61241 {Bundle[EMPTY_PARCEL]}] using it"
33265,1661030321.2289999,2022-08-20T14:18:41.229000-07:00,"CreateGeofenceAction : creating geofence at location Location[fused (stanford shopping center) hAcc=9.667 et=+8d7h9m22s604ms alt=-8.642381725305299 vAcc=27.64749 vel=1.2806634 sAcc=0.2408319 bear=201.61241 {Bundle[EMPTY_PARCEL]}]"

and then nothing until the following. this was a true geofence exit and not just me turning the trip off and on

33979,1661033709.3279998,2022-08-20T15:15:09.328000-07:00,"GeofenceExitIntentService : got geofence intent callback with type 2 and location Location[fused (El Camino and Castro) hAcc=48.9 et=+8d8h2m18s220ms alt=10.399999618530273 vAcc=5.7670794]"

shankari commented 2 years ago

We first poll for openpath

      08-20 14:11:12.428: +client 10190/com.google.android.gms[geofencer_provider]/9fdc48c6 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10320 gov.nrel.cims.openpath}]
      08-20 14:14:35.719: +client 10190/com.google.android.gms[geofencer_provider]/9fdc48c6 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10320 gov.nrel.cims.openpath}]

And then turn emission off and on

      08-20 14:18:12.423: +client 10268/gov.colorado.energyoffice.emission/b05f341d -> Request[@1ms HIGH_ACCURACY, minUpdateInterval=0s, waitForAccurateLocation, WorkSource{10268 gov.colorado.energyoffice.emission}]
      08-20 14:18:14.351: +client 10190/com.google.android.gms[geofencer_provider]/9fdc48c6 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10268 gov.colorado.energyoffice.emission}]
      08-20 14:18:17.685: +client 10268/gov.colorado.energyoffice.emission/d460bea2 -> Request[@30s HIGH_ACCURACY, minUpdateInterval=5s, waitForAccurateLocation, WorkSource{10268 gov.colorado.energyoffice.emission}]

and then we only poll for e-mission and then we don't have any locations for a while (apparently) and then we got to 15:15 and then we checked again.

      08-20 14:18:14.351: +client 10190/com.google.android.gms[geofencer_provider]/9fdc48c6 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10268 gov.colorado.energyoffice.emission}]
      08-20 14:18:20.929: +client 10190/com.google.android.gms[geofencer_provider]/9fdc48c6 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10268 gov.colorado.energyoffice.emission}]

      08-20 14:18:41.312: +client 10190/com.google.android.gms[geofencer_provider]/9fdc48c6 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}]

      08-20 14:18:41.360: delivered location[1] to 10190/com.google.android.gms[geofencer_provider]/9fdc48c6
      08-20 14:26:19.885: received LocationAvailability[false]
      08-20 14:37:46.809: received LocationAvailability[false]
      08-20 14:43:59.198: received LocationAvailability[false]
      08-20 14:49:12.684: -client 10190/com.google.android.gms[geofencer_provider]/9fdc48c6
      08-20 14:49:12.684: engine request = Request[OFF]
      08-20 14:49:12.692: received LocationAvailability[true]
      08-20 14:49:12.684: engine request = Request[OFF]

      08-20 15:11:14.273: +client 10190/com.google.android.gms[earthquake_alerting]/11d6a97a -> Request[@30m BALANCED_POWER_ACCURACY, minUpdateInterval=5m, minUpdateDistance=1000.0, THROTTLE_NEVER, WorkSource{10190 com.google.android.gms}]
....
      08-20 15:15:09.296: +client 10190/com.google.android.gms[geofencer_provider]/9fdc48c6 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10291 edu.berkeley.eecs.emission}]

So there seem to be two problems:

there's something that is periodically removing geofences (adding a new one? but we have seen pixel have two geofences before)
even when we do have geofences, it looks like location availability is frequently poor and there are large gaps between subsequent polls

shankari commented 2 years ago

Now, let's do the same analysis on the missing trips on my personal phone (in case the issue is with missing data plan on the SIM card). For example, the trip to the vet on Aug 10 was completely skipped.

No trip to the vet	My Aug 10 trips	Missing trip to vet	Missing trip from vet

shankari commented 2 years ago

tl;dr:

this does not appear to be the geofence issue; both apps show up all the time
it does seem to have big gaps in the polling; the GMS services keeps getting locations but the client for the apps does not poll for ~ 1 hour from 18:20 to 19:10
most importantly, this seems to be using com.google.gms[.contextmanager] while the trip to stanford that worked was using com.google.gms.[locationbase]. Of course, there does not appear to be any documentation about the difference between the two anywhere...

Looking around 18:00, when we ended the trip back from the hardware store, we get the following logs - note the big gap (almost 10 minutes!) between the request and the location delivery.

      08-10 17:58:20.944: +client 10279/gov.colorado.energyoffice.emission/db9dcf57 -> Request[@30s HIGH_ACCURACY, minUpdateInterval=5s, waitForAccurateLocation, WorkSource{10279 gov.colorado.energyoffice.emission}]
      08-10 17:58:20.959: engine request = Request[@30s HIGH_ACCURACY, WorkSource{10279 gov.colorado.energyoffice.emission}]
      08-10 17:58:21.012: +client 10298/gov.nrel.cims.openpath/4e1695a5 -> Request[@30s HIGH_ACCURACY, minUpdateInterval=5s, waitForAccurateLocation, WorkSource{10298 gov.nrel.cims.openpath}]
      08-10 17:58:21.029: engine request = Request[@30s HIGH_ACCURACY, WorkSource{10279 gov.colorado.energyoffice.emission, 10298 gov.nrel.cims.openpath}]
      08-10 18:07:23.532: delivered location[1] to 10279/gov.colorado.energyoffice.emission/db9dcf57
      08-10 18:07:23.544: delivered location[1] to 10298/gov.nrel.cims.openpath/4e1695a5

      08-10 18:08:06.703: delivered location[1] to 10279/gov.colorado.energyoffice.emission/db9dcf57
      08-10 18:08:06.712: delivered location[1] to 10298/gov.nrel.cims.openpath/4e1695a5

Then the high accuracy clients disconnect

      08-10 18:08:06.938: -client 10279/gov.colorado.energyoffice.emission/db9dcf57
      08-10 18:08:07.045: -client 10298/gov.nrel.cims.openpath/4e1695a5

and we end up with the geofence requests

      08-10 18:08:07.064: +client 10189/com.google.android.gms[.contextmanager]/61dc3361 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_ALWAYS, WorkSource{10279 gov.colorado.energyoffice.emission}]
      08-10 18:08:07.133: +client 10189/com.google.android.gms[.contextmanager]/61dc3361 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_ALWAYS, WorkSource{10279 gov.colorado.energyoffice.emission, 10298 gov.nrel.cims.openpath}]
      08-10 18:08:07.141: engine request = Request[@10m BALANCED_POWER_ACCURACY, WorkSource{10279 gov.colorado.energyoffice.emission, 10298 gov.nrel.cims.openpath}]

then, there are a lot of locations sent to the context manager until the client is disconnected

``` 08-10 18:08:07.141: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/61dc3361 08-10 18:08:07.141: received WIFI location[1] 08-10 18:08:07.145: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/61dc3361 08-10 18:08:07.146: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 18:13:08.228: received WIFI location[1] 08-10 18:13:08.237: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/61dc3361 08-10 18:13:08.238: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 18:13:08.247: received LocationAvailability[true] 08-10 18:13:08.251: received LocationAvailability[true] 08-10 18:13:29.693: received WIFI location[1] 08-10 18:13:29.699: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/61dc3361 08-10 18:13:29.702: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 18:13:50.690: received WIFI location[1] 08-10 18:13:50.703: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/61dc3361 08-10 18:13:50.704: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 18:14:12.704: received WIFI location[1] 08-10 18:14:12.711: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/61dc3361 08-10 18:14:12.714: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 18:19:14.287: received WIFI location[1] 08-10 18:19:14.293: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/61dc3361 08-10 18:19:14.294: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 18:19:35.741: received WIFI location[1] 08-10 18:19:35.750: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/61dc3361 08-10 18:19:35.751: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 18:20:44.463: received LocationAvailability[true] 08-10 18:20:44.483: -client 10189/com.google.android.gms[.contextmanager]/61dc3361 ```

This is when we are going to leave on the trip. We poll the contextmanager on behalf of both apps but disconnect immediately

      08-10 18:20:44.483: +client 10189/com.google.android.gms[.contextmanager]/61dc3361 -> Request[@1m8s BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_ALWAYS, WorkSource{10279 gov.colorado.energyoffice.emission, 10298 gov.nrel.cims.openpath}]
      08-10 18:20:44.491: received LocationAvailability[true]
      08-10 18:20:44.546: -client 10189/com.google.android.gms[.contextmanager]/6e29ac43

Then we poll on the behalf of the gms package with a 30m delay

      08-10 18:20:45.003: +client 10189/com.google.android.gms[.contextmanager]/6e29ac43 -> Request[@30m BALANCED_POWER_ACCURACY, minUpdateInterval=5m, minUpdateDistance=1000.0, THROTTLE_ALWAYS, WorkSource{10189 com.google.android.gms}]

And we send locations to the gms manager continuously, do not re-poll on behalf of the apps, and so do not exit the geofence

``` 08-10 18:23:32.216: received LocationAvailability[true] 08-10 18:23:33.916: received WIFI location[1] 08-10 18:23:33.918: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 18:23:33.925: received LocationAvailability[true] 08-10 18:28:35.945: received WIFI location[1] 08-10 18:28:35.951: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/6e29ac43 08-10 18:28:35.954: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 18:28:55.529: received WIFI location[1] 08-10 18:28:55.530: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 18:29:15.546: received WIFI location[1] 08-10 18:29:15.547: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 18:31:34.980: received WIFI location[1] 08-10 18:31:34.983: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 18:36:37.731: received WIFI location[1] 08-10 18:36:37.736: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/6e29ac43 08-10 18:36:37.738: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 18:36:57.730: received WIFI location[1] 08-10 18:36:57.731: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 18:37:18.698: received WIFI location[1] 08-10 18:37:18.701: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 18:38:53.739: received WIFI location[1] 08-10 18:38:53.740: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 18:43:55.851: received WIFI location[1] 08-10 18:43:55.852: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 18:44:17.465: received WIFI location[1] 08-10 18:44:17.467: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 18:49:37.300: received WIFI location[1] 08-10 18:49:37.302: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 18:49:57.806: received WIFI location[1] 08-10 18:49:57.808: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 18:50:20.752: received WIFI location[1] 08-10 18:50:20.755: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 18:55:22.207: received WIFI location[1] 08-10 18:55:22.208: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 18:55:42.634: received WIFI location[1] 08-10 18:55:42.636: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 18:56:03.644: received WIFI location[1] 08-10 18:56:03.650: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 18:56:24.627: received WIFI location[1] 08-10 18:56:24.629: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 18:56:45.715: received WIFI location[1] 08-10 18:56:45.717: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 19:01:47.808: received WIFI location[1] 08-10 19:01:47.815: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 19:02:08.665: received WIFI location[1] 08-10 19:02:08.666: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 19:02:33.089: received WIFI location[1] 08-10 19:02:33.090: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 08-10 19:03:07.666: received WIFI location[1] 08-10 19:03:07.667: delivered location[1] to 10189/com.google.android.gms[.contextmanager]/d220e2c8 ```

Note that we still have both geofences defined, so that is not the problem.

    Package: gov.colorado.energyoffice.emission, count: 1
        Geofence[CIRCLE id:DYNAMIC_EXIT_GEOFENCE transitions:2 (my house) 100m, resp=5s, dwell=-1ms, @-1] it=2, d=5 IN dwelled gov.colorado.energyoffice.emission
    Package: gov.nrel.cims.openpath, count: 1
        Geofence[CIRCLE id:DYNAMIC_EXIT_GEOFENCE transitions:2 (my house) 100m, resp=5s, dwell=-1ms, @-1] it=2, d=5 IN dwelled gov.nrel.cims.openpath

shankari commented 2 years ago

Returning to the Indian store trip (https://github.com/e-mission/e-mission-docs/issues/774#issuecomment-1217459181), leaving around 5:30pm and departing from the store at around 6:20pm, we get the following.

To note:

this also uses location_base, so location_base vs. context_manager does not appear to be the issue
none of the GeofencerStateMachine logs seem to involve location cmds, which does seem to be the issue 😄

locations to app from 17:27 to 17:30

``` 08-16 17:27:22.296: +client 10189/com.google.android.gms[.location_base]/ea31a310 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10279 gov.colorado.energyoffice.emission, 10298 gov.nrel.cims.openpath}] 08-16 17:27:22.369: engine request = Request[@5m BALANCED_POWER_ACCURACY, WorkSource{10279 gov.colorado.energyoffice.emission, 10298 gov.nrel.cims.openpath}] 08-16 17:27:22.369: delivered location[1] to 10189/com.google.android.gms[.location_base]/ea31a310 08-16 17:27:22.370: received WIFI location[1] 08-16 17:27:22.382: delivered location[1] to 10189/com.google.android.gms[.location_base]/ea31a310 08-16 17:27:22.387: delivered location[1] to 10189/com.google.android.gms[.location_base]/fdf3309c 08-16 17:30:23.792: -client 10189/com.google.android.gms[.location_base]/ea31a310 ```

Locations to apps from 17:30 to 17:33

``` 08-16 17:30:23.792: +client 10189/com.google.android.gms[.location_base]/ea31a310 -> Request[@5m BALANCED_POWER_ACCURACY, minUpdateInterval=5s, THROTTLE_NEVER, WorkSource{10279 gov.colorado.energyoffice.emission, 10298 gov.nrel.cims.openpath}] 08-16 17:30:23.800: delivered location[1] to 10189/com.google.android.gms[.location_base]/ea31a310 08-16 17:31:43.150: received WIFI location[1] 08-16 17:31:43.161: delivered location[1] to 10189/com.google.android.gms[.location_base]/ea31a310 08-16 17:31:43.163: delivered location[1] to 10189/com.google.android.gms[.location_base]/fdf3309c 08-16 17:31:43.172: received LocationAvailability[true] 08-16 17:32:03.999: received WIFI location[1] 08-16 17:32:04.005: delivered location[1] to 10189/com.google.android.gms[.location_base]/ea31a310 08-16 17:32:04.006: delivered location[1] to 10189/com.google.android.gms[.location_base]/fdf3309c 08-16 17:32:24.925: received WIFI location[1] 08-16 17:32:24.932: delivered location[1] to 10189/com.google.android.gms[.location_base]/ea31a310 08-16 17:32:24.934: delivered location[1] to 10189/com.google.android.gms[.location_base]/fdf3309c 08-16 17:32:45.026: received WIFI location[1] 08-16 17:32:45.032: delivered location[1] to 10189/com.google.android.gms[.location_base]/ea31a310 08-16 17:32:45.035: delivered location[1] to 10189/com.google.android.gms[.location_base]/fdf3309c 08-16 17:33:24.041: received LocationAvailability[true] 08-16 17:33:24.069: received LocationAvailability[true] 08-16 17:33:24.179: -client 10189/com.google.android.gms[.location_base]/ea31a310 ```

locations to the gms service from 17:33 to the end of the logs. Note that the client was actually registered the previous night, but it is only unregistered now

``` 08-15 23:22:48.389: +client 10189/com.google.android.gms[.location_base]/3a157252 -> Request[@30m BALANCED_POWER_ACCURACY, minUpdateInterval=5m, minUpdateDistance=1000.0, THROTTLE_NEVER, WorkSource{10189 com.google.android.gms}] 08-16 17:33:24.179: engine request = Request[@30m BALANCED_POWER_ACCURACY, minUpdateDistance=1000.0, WorkSource{10189 com.google.android.gms}] 08-16 17:33:24.218: received LocationAvailability[true] 08-16 17:33:26.076: received WIFI location[1] 08-16 17:33:26.086: delivered location[1] to 10189/com.google.android.gms[.location_base]/fdf3309c 08-16 17:33:26.102: received LocationAvailability[true] 08-16 17:33:26.170: -client 10189/com.google.android.gms[.location_base]/3a157252 08-16 17:33:26.170: engine request = Request[OFF] 08-16 17:33:26.184: received LocationAvailability[true] 08-16 17:33:26.733: +client 10189/com.google.android.gms[.location_base]/3a157252 -> Request[@30m BALANCED_POWER_ACCURACY, minUpdateInterval=5m, minUpdateDistance=1000.0, THROTTLE_NEVER, WorkSource{10189 com.google.android.gms}] 08-16 17:33:26.742: delivered location[1] to 10189/com.google.android.gms[.location_base]/3a157252 08-16 17:33:36.538: received WIFI location[1] 08-16 17:33:36.539: received LocationAvailability[true] 08-16 17:33:36.539: delivered location[1] to 10189/com.google.android.gms[.location_base]/fdf3309c 08-16 17:33:56.489: received LocationAvailability[true] 08-16 17:38:38.606: received WIFI location[1] 08-16 17:38:38.607: delivered location[1] to 10189/com.google.android.gms[.location_base]/fdf3309c 08-16 17:38:38.612: delivered location[1] to 10189/com.google.android.gms[.location_base]/3a157252 08-16 17:38:38.613: received LocationAvailability[true] 08-16 17:38:58.208: received LocationAvailability[true] 08-16 17:43:25.590: engine request = Request[@30m BALANCED_POWER_ACCURACY, minUpdateDistance=1000.0, WorkSource{10189 com.google.android.gms}] 08-16 17:43:25.640: received LocationAvailability[true] 08-16 17:43:26.234: received WIFI location[1] 08-16 17:43:26.236: delivered location[1] to 10189/com.google.android.gms[.location_base]/fdf3309c 08-16 17:43:26.244: delivered location[1] to 10189/com.google.android.gms[.location_base]/3a157252 08-16 17:43:26.253: received LocationAvailability[true] 08-16 17:49:08.083: received WIFI location[1] 08-16 17:49:08.095: delivered location[1] to 10189/com.google.android.gms[.location_base]/fdf3309c 08-16 17:49:08.115: received LocationAvailability[true] 08-16 17:49:28.898: received WIFI location[1] 08-16 17:49:28.900: delivered location[1] to 10189/com.google.android.gms[.location_base]/fdf3309c 08-16 17:49:49.910: received WIFI location[1] 08-16 17:49:49.912: delivered location[1] to 10189/com.google.android.gms[.location_base]/fdf3309c ```

     rec[0]: time=08-16 17:43:29.183 processed=FastMovingActivityState org=FastMovingActivityState dest=<null> what=SM_SAVE_ACTIVITY_STATE_CMD
     rec[1]: time=08-16 17:43:39.178 processed=FastMovingActivityState org=FastMovingActivityState dest=<null> what=SM_SYSTEM_EVENT_CMD
     rec[2]: time=08-16 17:44:05.425 processed=FastMovingActivityState org=FastMovingActivityState dest=<null> what=SM_SYSTEM_EVENT_CMD
     rec[3]: time=08-16 17:44:05.924 processed=FastMovingActivityState org=FastMovingActivityState dest=<null> what=SM_SYSTEM_EVENT_CMD
     rec[4]: time=08-16 17:44:19.520 processed=FastMovingActivityState org=FastMovingActivityState dest=<null> what=SM_SYSTEM_EVENT_CMD
     rec[5]: time=08-16 17:45:39.239 processed=FastMovingActivityState org=FastMovingActivityState dest=<null> what=SM_SAVE_ACTIVITY_STATE_CMD
     rec[6]: time=08-16 17:47:49.090 processed=FastMovingActivityState org=FastMovingActivityState dest=<null> what=SM_SYSTEM_EVENT_CMD
     rec[7]: time=08-16 17:48:01.900 processed=FastMovingActivityState org=FastMovingActivityState dest=<null> what=SM_SYSTEM_EVENT_CMD
     rec[8]: time=08-16 17:49:54.124 processed=FastMovingActivityState org=FastMovingActivityState dest=<null> what=SM_SYSTEM_EVENT_CMD
     rec[9]: time=08-16 17:50:04.760 processed=FastMovingActivityState org=FastMovingActivityState dest=<null> what=SM_SYSTEM_EVENT_CMD

shankari commented 2 years ago

Quick note:

I turned tracking off and on for all three apps on the pixel

08-20 20:52:08.093 10291 16219 16219 I TripDiaryStateMachineRcvr: TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@72ff758, Intent { act=local.transition.initialize flg=0x10 pkg=edu.berkeley.eecs.emission cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.TripDiaryStateMachineReceiver }) called
08-20 20:52:08.270 10291 16219 16219 I TripDiaryStateMachineRcvr: TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@72ff758, Intent { act=local.transition.initialize flg=0x10 pkg=edu.berkeley.eecs.emission cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.TripDiaryStateMachineReceiver }) called
08-20 20:52:27.642 10268 16158 16158 I TripDiaryStateMachineRcvr: TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@d848b1c, Intent { act=local.transition.initialize flg=0x10 pkg=gov.colorado.energyoffice.emission cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineReceiver }) called
08-20 20:52:27.674 10268 16158 16158 I TripDiaryStateMachineRcvr: TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@d848b1c, Intent { act=local.transition.initialize flg=0x10 pkg=gov.colorado.energyoffice.emission cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineReceiver }) called
08-20 20:52:46.602 10320 16183 16183 I TripDiaryStateMachineRcvr: TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@9294ff9, Intent { act=local.transition.initialize flg=0x10 pkg=gov.nrel.cims.openpath cmp=gov.nrel.cims.openpath/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineReceiver }) called
08-20 20:52:46.638 10320 16183 16183 I TripDiaryStateMachineRcvr: TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@9294ff9, Intent { act=local.transition.initialize flg=0x10 pkg=gov.nrel.cims.openpath cmp=gov.nrel.cims.openpath/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineReceiver }) called

and ended up with only one geofence instead of three.

    Geofencer State:
    Registered geofences:
    Active Geofences:
    Package: gov.nrel.cims.openpath, count: 1
        Geofence[CIRCLE id:DYNAMIC_EXIT_GEOFENCE transitions:2 (my house) 100m, resp=5s, dwell=-1ms, @-1] it=2, d=0 IN dwelled gov.nrel.cims.openpath

    Location updater: NearbyGeofenceLocationUpdater.
        Monitoring all now.
        Sentinel geofence: null
    SystemMemoryCache for com.google.android.location.internal.GoogleLocationManagerService
     type = 2
     id = 164c2c8a-58e8-4e50-9051-190698ff4f9c
     cacheData = [PendingIntentCacheItem [mPendingIntent=PendingIntent{d10ce9d: android.os.BinderProxy@409957a}, mExternalKey=f7ba9542-4f70-4ea3-9bb0-30c439b625ff, mAssociatedGeofenceIds=[DYNAMIC_EXIT_GEOFENCE]]]

The weird part is that I know for a fact that we have had two apps have geofences at the same time before on the Pixel,

pixel_detected_library_trip_friday_aug_12/bugreport-flame-SQ3A.220705.003.A1-2022-08-12-11-42-52.txt:    Active Geofences:
pixel_detected_library_trip_friday_aug_12/bugreport-flame-SQ3A.220705.003.A1-2022-08-12-11-42-52.txt-    Package: com.fabmoqc.mamobilite, count: 1
pixel_detected_library_trip_friday_aug_12/bugreport-flame-SQ3A.220705.003.A1-2022-08-12-11-42-52.txt-        Geofence[CIRCLE id:DYNAMIC_EXIT_GEOFENCE transitions:2 (my house) 100m, resp=5s, dwell=-1ms, @-1] it=2, d=0 IN dwelled com.fabmoqc.mamobilite
pixel_detected_library_trip_friday_aug_12/bugreport-flame-SQ3A.220705.003.A1-2022-08-12-11-42-52.txt-    Package: edu.berkeley.eecs.emission, count: 1
pixel_detected_library_trip_friday_aug_12/bugreport-flame-SQ3A.220705.003.A1-2022-08-12-11-42-52.txt-        Geofence[CIRCLE id:DYNAMIC_EXIT_GEOFENCE transitions:2 (my house) 100m, resp=5s, dwell=-1ms, @-1] it=2, d=0 IN dwelled edu.berkeley.eecs.emission
pixel_detected_library_trip_friday_aug_12/bugreport-flame-SQ3A.220705.003.A1-2022-08-12-11-42-52.txt-    Package: gov.colorado.energyoffice.emission, count: 1
pixel_detected_library_trip_friday_aug_12/bugreport-flame-SQ3A.220705.003.A1-2022-08-12-11-42-52.txt-        Geofence[CIRCLE id:DYNAMIC_EXIT_GEOFENCE transitions:2 (my house) 100m, resp=5s, dwell=-1ms, @-1] it=2, d=0 IN dwelled gov.colorado.energyoffice.emission
pixel_detected_library_trip_friday_aug_12/bugreport-flame-SQ3A.220705.003.A1-2022-08-12-11-42-52.txt-    Package: gov.nrel.cims.openpath, count: 1
pixel_detected_library_trip_friday_aug_12/bugreport-flame-SQ3A.220705.003.A1-2022-08-12-11-42-52.txt-        Geofence[CIRCLE id:DYNAMIC_EXIT_GEOFENCE transitions:2 (my house) 100m, resp=5s, dwell=-1ms, @-1] it=2, d=0 IN dwelled gov.nrel.cims.openpath
pixel_detected_library_trip_friday_aug_12/bugreport-flame-SQ3A.220705.003.A1-2022-08-12-11-42-52.txt-
pixel_detected_library_trip_friday_aug_12/bugreport-flame-SQ3A.220705.003.A1-2022-08-12-11-42-52.txt-    Location updater: NearbyGeofenceLocationUpdater.

so I don't know how this changed...

I guess all of them just created new geofence on install so this wasn't a problem?! Will try to append the package name to the geofence name as a temporary fix although this is not a super high priority fix.

shankari commented 2 years ago

wrt long-term fix, it seems like we should probably re-implement a very simple version of our own geofence algorithm. (1) For anything other than walking, we can simply generate a geofence_exit since it is unlikely to be walking around inside a building. (2) For walking, let's think about how much time it takes to cover 100 m

walking speed is around 3mph = around 5kmph
time to cover 100m = (100 * 60) / 5000 = 1.2 mins ~ 1-2 min
- use cases: a. true positive: user has started walking and is continuing to walk at a steady pace
  - when walk transition is detected, schedule a location read after 2 mins
  - location > 100m -> geofence_exit
  - location < 100m, schedule another location read after 2 mins b. true negative: user has started walking, but stops within 100m
  - when walk transition is detected, schedule a location read after 2 mins
  - when still transition is detected, cancel location read c. complex true positive: user has started walking, but stops at intersections every minute
  - this could lead to an infinite postponment of the detection because we would schedule a location read, cancel it when stopped, reschedule it to 2 mins out, recancel it when stopped etc
  - simple workaround is to also check the location when the walk transition occurs
  - if it is > 100m away, just generate the geofence transition anyway
  - so once we get > 100m, the next time we stop and start, we will re-generate the transition and avoid starvation.
- so the final algorithm is:
if we detect a walk transition, check to see if we are 100m from the previous geofence location
if yes, generate a geofence exit
else, schedule a location read after 2 mins and move to a 'checking_for_geofence_exit` state
- when we receive the location, if it is > 100m from the last geofence location, generate a geofence exit
  - else if we received a still transition in the middle, give up
  - else schedule a location read after 2 more mins

How should we structure this code?

Should we create a new state in the full FSM, or should we create a little "duplicate geofence" module with its own internal state that just generates geofence_exit transitions as needed?
- Answer: we will create a "geofence" module to be a little "duplicate geofence" module with its own internal state. This allows it to be either a parallel module to the existing geofence module (current choice) or potentially, a drop-in replacement for the future.