Device Tracker Latitude/Longitude is not set is still firing too much

[03397]

After upgrade places to the latest version, inside home assistant I am getting

[custom_components.places.sensor] (angela_places) Device Tracker (device_tracker.angelamobile) Latitude/Longitude is not set or is not a number. Not Proceeding with Track State Change Update.

I cannot see anything problematic coming from the gpslogger inside home assistant

[Snuffy2]

It's just a warning and you can probably safely ignore it if your places sensor is working ok. It just means when it went to update, the device_tracker didn't have a Lat/Long defined. That may have been at HA startup and places was trying to update before the device_tracker had fully loaded.

I'm going to move this warning to a different point in the update process in the next version, but I'm not sure if it will change you seeing the warning.

[03397]

Most probably you are right and the places component loads before the successful load of the gpslogger that is why it is complaining. It just writes warnings in the log files which shouldn't be there during a restart. Can you give it a grace period before the warning to appear in the logger so it will give sufficient tome for all the components to load successfully? Is there another workaround to avoid that?

[Snuffy2]

Please give v2.5 a try. I changed the settings so places should now start later in the HA startup process. Additionally, I moved the warning itself into a different part of places so hopefully both combined improve the experience.

[ildar170975]

I still see these messages:

2023-09-28 16:45:54.170 WARNING (SyncWorker_23) [custom_components.places.sensor] (place_iphone_5s_32) Tracked Entity (sensor.tracker_common_iphone_5s_32) Latitude/Longitude is not set or is not a number. Not Proceeding with Update.

they are flooded my Log. Not sure if I am using the latest version since it still shows "2.5".

[Snuffy2]

You say flooding your logs. So it is continuing to show even after startup? If so, similar to #214, please enable debug logging and post some logs of when it is firing incorrectly or excessively.

[ildar170975]

So it is continuing to show even after startup?

Unfortunately, yes. Had to hide them:

  filters:
    custom_components.places.sensor:
      - "Tracked Entity (.*) Latitude/Longitude is not set or is not a number. Not Proceeding with Update"

Then I removed this filter & enabled the debug logging:

logger:
  default: warn
  logs:
    custom_components.sensor.places: debug

and see this: 2023-09-29 19:08:00.141 WARNING (SyncWorker_11) [custom_components.places.sensor] (place_samsung_p6800) Tracked Entity (sensor.tracker_common_samsung_p6800) Latitude/Longitude is not set or is not a number. Not Proceeding with Update. 2023-09-29 19:09:00.142 WARNING (SyncWorker_5) [custom_components.places.sensor] (place_samsung_p6800) Tracked Entity (sensor.tracker_common_samsung_p6800) Latitude/Longitude is not set or is not a number. Not Proceeding with Update. 2023-09-29 19:10:00.150 WARNING (SyncWorker_13) [custom_components.places.sensor] (place_samsung_p6800) Tracked Entity (sensor.tracker_common_samsung_p6800) Latitude/Longitude is not set or is not a number. Not Proceeding with Update. 2023-09-29 19:11:00.141 WARNING (SyncWorker_10) [custom_components.places.sensor] (place_samsung_p6800) Tracked Entity (sensor.tracker_common_samsung_p6800) Latitude/Longitude is not set or is not a number. Not Proceeding with Update. 2023-09-29 19:12:00.139 WARNING (SyncWorker_26) [custom_components.places.sensor] (place_samsung_p6800) Tracked Entity (sensor.tracker_common_samsung_p6800) Latitude/Longitude is not set or is not a number. Not Proceeding with Update. 2023-09-29 19:13:00.142 WARNING (SyncWorker_0) [custom_components.places.sensor] (place_samsung_p6800) Tracked Entity (sensor.tracker_common_samsung_p6800) Latitude/Longitude is not set or is not a number. Not Proceeding with Update.

Currently only one device (samsung_p6800) is having empty latitude, longitude (null) - the device is switched off for a week. These messages come every 1 minute. Imagine what happens when there are more devices... For instance, sometimes Life360 device trackers are not properly setup and lat/long are empty too - so more messages come to Log.

[Snuffy2]

I'm going to re-open this one, but close #214

[Snuffy2]

So a few things:

1. places should only be triggering an update every 10 minutes if there is no movement or updates from the device_tracker. Even though the device is off, is there something that is causing the device_tracker itself to update every minute (thus triggering places to update)?
2. In order to investigate number 1 above further, I will also need the actual Debug logs. What you posted is still missing the Debug level information. I've put below an example of what a working and non-working places sensor's Debug logs should look like.
3. There is still something wrong with the code for this warning. It is only supposed to fire once when Lat/Long is missing and then not fire again until Lat/Long comes back and then disappears again (if that ever happens again). As above, if you can post the full debug logs, I may get a better idea about what is happening.

2023-09-29 17:52:35.603 INFO (MainThread) [custom_components.places.sensor] (Test Person Snuffy2) [Init] Places sensor: Test Person Snuffy2
2023-09-29 17:52:35.603 DEBUG (MainThread) [custom_components.places.sensor] (Test Person Snuffy2) [Init] System Locale: ('en_US', 'UTF-8')
2023-09-29 17:52:35.604 DEBUG (MainThread) [custom_components.places.sensor] (Test Person Snuffy2) [Init] System Locale Date Format: %m/%d/%y
2023-09-29 17:52:35.604 DEBUG (MainThread) [custom_components.places.sensor] (Test Person Snuffy2) [Init] HASS TimeZone: America/New_York
2023-09-29 17:52:35.604 DEBUG (MainThread) [custom_components.places.sensor] (Test Person Snuffy2) [Init] entity_id: sensor.test_new_name
2023-09-29 17:52:35.604 DEBUG (MainThread) [custom_components.places.sensor] (Test Person Snuffy2) [Init] JSON Filename: places-13a643951fe671eda048fcc8ac6fd97a.json
2023-09-29 17:52:35.610 DEBUG (MainThread) [custom_components.places.sensor] (Test Person Snuffy2) [Init] No JSON file to import (places-13a643951fe671eda048fcc8ac6fd97a.json): [Errno 2] No such file or directory: 'custom_components/places/json_sensors/places-13a643951fe671eda048fcc8ac6fd97a.json'
2023-09-29 17:52:35.774 INFO (MainThread) [custom_components.places.sensor] (Test Person Snuffy2) [Init] Tracked Entity ID: person.snuffy2
2023-09-29 17:52:35.774 INFO (MainThread) [custom_components.places.sensor] (trackattr) [Init] Places sensor: trackattr
2023-09-29 17:52:35.774 DEBUG (MainThread) [custom_components.places.sensor] (trackattr) [Init] System Locale: ('en_US', 'UTF-8')
2023-09-29 17:52:35.775 DEBUG (MainThread) [custom_components.places.sensor] (trackattr) [Init] System Locale Date Format: %m/%d/%y
2023-09-29 17:52:35.775 DEBUG (MainThread) [custom_components.places.sensor] (trackattr) [Init] HASS TimeZone: America/New_York
2023-09-29 17:52:35.775 DEBUG (MainThread) [custom_components.places.sensor] (trackattr) [Init] entity_id: sensor.test_tracker_2
2023-09-29 17:52:35.775 DEBUG (MainThread) [custom_components.places.sensor] (trackattr) [Init] JSON Filename: places-a5277bee49876e28399208ef14cf901d.json
2023-09-29 17:52:35.782 DEBUG (MainThread) [custom_components.places.sensor] (trackattr) [Init] Sensor Attributes Imported from JSON file
2023-09-29 17:52:35.907 INFO (MainThread) [custom_components.places.sensor] (trackattr) [Init] Tracked Entity ID: device_tracker.trackattr
2023-09-29 17:52:35.913 INFO (SyncWorker_0) [custom_components.places.sensor] (Test Person Snuffy2) Starting Scan Interval Update (Tracked Entity: person.snuffy2)
2023-09-29 17:52:35.914 WARNING (SyncWorker_0) [custom_components.places.sensor] (Test Person Snuffy2) Tracked Entity (person.snuffy2) Latitude/Longitude is not set or is not a number. Not Proceeding with Update.
2023-09-29 17:52:35.933 INFO (SyncWorker_4) [custom_components.places.sensor] (trackattr) Starting Scan Interval Update (Tracked Entity: device_tracker.trackattr)
2023-09-29 17:52:35.935 DEBUG (SyncWorker_4) [custom_components.places.sensor] (trackattr) [is_devicetracker_set] proceed_with_update: 1
2023-09-29 17:52:35.935 DEBUG (SyncWorker_4) [custom_components.places.sensor] (trackattr) GPS Accuracy: 15.0
2023-09-29 17:52:35.936 DEBUG (SyncWorker_4) [custom_components.places.sensor] (trackattr) [is_devicetracker_set] proceed_with_update: 1
2023-09-29 17:52:35.936 DEBUG (SyncWorker_4) [custom_components.places.sensor] (trackattr) Previous State: Exxon, Harrisburg, PA
2023-09-29 17:52:35.936 DEBUG (SyncWorker_4) [custom_components.places.sensor] (trackattr) Previous last_place_name: World's Largest Ball of Sisal Twine
2023-09-29 17:52:35.936 DEBUG (SyncWorker_4) [custom_components.places.sensor] (trackattr) Previous place is Place Name, last_place_name is set: Exxon
2023-09-29 17:52:35.936 DEBUG (SyncWorker_4) [custom_components.places.sensor] (trackattr) last_place_name (Initial): Exxon
2023-09-29 17:52:35.937 DEBUG (SyncWorker_4) [custom_components.places.sensor] (trackattr) Tracked Entity Zone: not_home
2023-09-29 17:52:35.937 DEBUG (SyncWorker_4) [custom_components.places.sensor] (trackattr) Previous Location: 40.2667,-76.88636
2023-09-29 17:52:35.937 DEBUG (SyncWorker_4) [custom_components.places.sensor] (trackattr) Current Location: 40.2667,-76.88636
2023-09-29 17:52:35.938 DEBUG (SyncWorker_4) [custom_components.places.sensor] (trackattr) Home Location: 41.02390078957104,-74.14124071598054
2023-09-29 17:52:35.938 INFO (SyncWorker_4) [custom_components.places.sensor] (trackattr) Distance from home [home]: 246.937 km
2023-09-29 17:52:35.938 INFO (SyncWorker_4) [custom_components.places.sensor] (trackattr) Travel Direction: stationary
2023-09-29 17:52:35.940 INFO (SyncWorker_4) [custom_components.places.sensor] (trackattr) Meters traveled since last update: 0.0
2023-09-29 17:52:35.940 DEBUG (SyncWorker_4) [custom_components.places.sensor] (trackattr) [update_coordinates_and_distance] proceed_with_update: 1
2023-09-29 17:52:35.940 INFO (SyncWorker_4) [custom_components.places.sensor] (trackattr) Not performing update because coordinates are identical
2023-09-29 17:52:35.940 DEBUG (SyncWorker_4) [custom_components.places.sensor] (trackattr) [determine_if_update_needed] proceed_with_update: 2
2023-09-29 17:52:35.941 DEBUG (SyncWorker_4) [custom_components.places.sensor] (trackattr) Reverting attributes back to before the update started
2023-09-29 17:52:35.941 INFO (SyncWorker_4) [custom_components.places.sensor] (trackattr) End of Update
2023-09-29 17:52:35.968 DEBUG (MainThread) [custom_components.places.sensor] (trackattr) [Init] Subscribed to Tracked Entity state change events
2023-09-29 17:52:35.977 DEBUG (SyncWorker_0) [custom_components.places.sensor] (Test Person Snuffy2) Tracked Entity (person.snuffy2) details: <state person.snuffy2=unknown; editable=True, id=snuffy2, source=person.snuffy2, user_id=b9c8a3858b53436ca070bc69faaaf223, device_trackers=[], friendly_name=Snuffy2 @ 2023-09-29T17:47:07.630167-04:00>
2023-09-29 17:52:35.977 DEBUG (SyncWorker_0) [custom_components.places.sensor] (Test Person Snuffy2) [is_devicetracker_set] proceed_with_update: 0
2023-09-29 17:52:35.977 DEBUG (SyncWorker_0) [custom_components.places.sensor] (Test Person Snuffy2) Reverting attributes back to before the update started
2023-09-29 17:52:35.978 INFO (SyncWorker_0) [custom_components.places.sensor] (Test Person Snuffy2) End of Update
2023-09-29 17:52:35.983 DEBUG (MainThread) [custom_components.places.sensor] (Test Person Snuffy2) [Init] Subscribed to Tracked Entity state change events
2023-09-29 18:02:36.003 INFO (SyncWorker_0) [custom_components.places.sensor] (trackattr) Starting Scan Interval Update (Tracked Entity: device_tracker.trackattr)
2023-09-29 18:02:36.006 DEBUG (SyncWorker_0) [custom_components.places.sensor] (trackattr) [is_devicetracker_set] proceed_with_update: 1
2023-09-29 18:02:36.007 DEBUG (SyncWorker_0) [custom_components.places.sensor] (trackattr) GPS Accuracy: 15.0
2023-09-29 18:02:36.008 DEBUG (SyncWorker_0) [custom_components.places.sensor] (trackattr) [is_devicetracker_set] proceed_with_update: 1
2023-09-29 18:02:36.008 DEBUG (SyncWorker_0) [custom_components.places.sensor] (trackattr) Previous State: Exxon, Harrisburg, PA
2023-09-29 18:02:36.008 DEBUG (SyncWorker_0) [custom_components.places.sensor] (trackattr) Previous last_place_name: World's Largest Ball of Sisal Twine
2023-09-29 18:02:36.014 DEBUG (SyncWorker_0) [custom_components.places.sensor] (trackattr) Previous place is Place Name, last_place_name is set: Exxon
2023-09-29 18:02:36.015 DEBUG (SyncWorker_0) [custom_components.places.sensor] (trackattr) last_place_name (Initial): Exxon
2023-09-29 18:02:36.017 DEBUG (SyncWorker_0) [custom_components.places.sensor] (trackattr) Tracked Entity Zone: not_home
2023-09-29 18:02:36.018 DEBUG (SyncWorker_0) [custom_components.places.sensor] (trackattr) Previous Location: 40.2667,-76.88636
2023-09-29 18:02:36.019 DEBUG (SyncWorker_0) [custom_components.places.sensor] (trackattr) Current Location: 40.2667,-76.88636
2023-09-29 18:02:36.019 DEBUG (SyncWorker_0) [custom_components.places.sensor] (trackattr) Home Location: 44.02390078957104,-71.14124071598054
2023-09-29 18:02:36.019 INFO (SyncWorker_0) [custom_components.places.sensor] (trackattr) Distance from home [home]: 246.937 km
2023-09-29 18:02:36.020 INFO (SyncWorker_0) [custom_components.places.sensor] (trackattr) Travel Direction: stationary
2023-09-29 18:02:36.020 INFO (SyncWorker_0) [custom_components.places.sensor] (trackattr) Meters traveled since last update: 0.0
2023-09-29 18:02:36.021 DEBUG (SyncWorker_0) [custom_components.places.sensor] (trackattr) [update_coordinates_and_distance] proceed_with_update: 1
2023-09-29 18:02:36.021 INFO (SyncWorker_0) [custom_components.places.sensor] (trackattr) Not performing update because coordinates are identical
2023-09-29 18:02:36.021 DEBUG (SyncWorker_0) [custom_components.places.sensor] (trackattr) [determine_if_update_needed] proceed_with_update: 2
2023-09-29 18:02:36.022 INFO (SyncWorker_5) [custom_components.places.sensor] (Test Person Snuffy2) Starting Scan Interval Update (Tracked Entity: person.snuffy2)
2023-09-29 18:02:36.023 WARNING (SyncWorker_5) [custom_components.places.sensor] (Test Person Snuffy2) Tracked Entity (person.snuffy2) Latitude/Longitude is not set or is not a number. Not Proceeding with Update.
2023-09-29 18:02:36.022 DEBUG (SyncWorker_0) [custom_components.places.sensor] (trackattr) Reverting attributes back to before the update started
2023-09-29 18:02:36.025 INFO (SyncWorker_0) [custom_components.places.sensor] (trackattr) End of Update
2023-09-29 18:02:36.041 DEBUG (SyncWorker_5) [custom_components.places.sensor] (Test Person Snuffy2) Tracked Entity (person.snuffy2) details: <state person.snuffy2=unknown; editable=True, id=snuffy2, user_id=b9c8a3858b53436ca070bc69faaaf223, device_trackers=[], friendly_name=Snuffy2 @ 2023-09-29T17:47:07.630167-04:00>
2023-09-29 18:02:36.041 DEBUG (SyncWorker_5) [custom_components.places.sensor] (Test Person Snuffy2) [is_devicetracker_set] proceed_with_update: 0
2023-09-29 18:02:36.042 DEBUG (SyncWorker_5) [custom_components.places.sensor] (Test Person Snuffy2) Reverting attributes back to before the update started
2023-09-29 18:02:36.043 INFO (SyncWorker_5) [custom_components.places.sensor] (Test Person Snuffy2) End of Update

[ildar170975]

2. What you posted is still missing the Debug level information

Yes, I noticed it too. Here is my logger code:

logger:
  default: warn
  logs:
    custom_components.sensor.places: debug
  filters:
    ...

This code seems to work - at least "filters" part does work. Also, currently I have no filters for "places".

[Snuffy2]

Ahhh, I see the issue with your debug logging setting. You need to change it to:

logger:
  default: warning
  logs:
    custom_components.places: debug

You have: custom_components.sensor.places: debug remove sensor

[ildar170975]

remove sensor

!!!! Super. Now I wonder why I added it some time ago then commented, then uncommented today... Was it always w/o "sensor"? Seems to be always .... Mea culpa...

[Snuffy2]

It's been the same for at least a year.

[ildar170975]

@Snuffy2 I prepared a Log with debug info. Some lines contain a private info including addresses. May be what you need is only related to the entity which mentioned in these messages?

2023-09-29 19:11:00.141 WARNING (SyncWorker_10) [custom_components.places.sensor] (place_samsung_p6800) Tracked Entity (sensor.tracker_common_samsung_p6800) Latitude/Longitude is not set or is not a number. Not Proceeding with Update.

Then what I see in Log:

2023-09-30 03:17:00.180 INFO (SyncWorker_24) [custom_components.places.sensor] (place_samsung_p6800) Starting Track State Change Update (Tracked Entity: sensor.tracker_common_samsung_p6800)
2023-09-30 03:17:00.180 WARNING (SyncWorker_24) [custom_components.places.sensor] (place_samsung_p6800) Tracked Entity (sensor.tracker_common_samsung_p6800) Latitude/Longitude is not set or is not a number. Not Proceeding with Update.
2023-09-30 03:17:00.180 DEBUG (SyncWorker_24) [custom_components.places.sensor] (place_samsung_p6800) Tracked Entity (sensor.tracker_common_samsung_p6800) details: <state sensor.tracker_common_samsung_p6800=not_home; long_state=latitude=None, longitude=None, last_seen=1696032777.104532, place_source_type=router, place_source=iPhoneDetect, place=not_home, place_delta=4.1, place_alert=on, battery_level_source=Traccar, battery_level=1, battery_level_delta=4.1, battery_level_alert=on, battery_charging_source=Traccar, battery_charging=unavailable, battery_charging_delta=4.1, battery_charging_alert=on, place_formatted=Away, last_seen=2023-09-30T03:12:57.104532+03:00, latitude=None, longitude=None, source_type=router, place_source=iPhoneDetect, place=not_home, place_delta=4.1, place_alert=on, battery_level_source=Traccar, battery_level=1, battery_level_delta=4.1, battery_level_alert=on, battery_charging_source=Traccar, battery_charging=unavailable, battery_charging_delta=4.1, battery_charging_alert=on, entity_picture=/local/images/devices/samsung_p6800.png, friendly_name=Samsung P6800, icon=mdi:tablet @ 2023-09-30T03:15:05.695301+03:00>
2023-09-30 03:17:00.180 DEBUG (SyncWorker_24) [custom_components.places.sensor] (place_samsung_p6800) [is_devicetracker_set] proceed_with_update: 0
2023-09-30 03:17:00.181 DEBUG (SyncWorker_24) [custom_components.places.sensor] (place_samsung_p6800) Reverting attributes back to before the update started
2023-09-30 03:17:00.181 INFO (SyncWorker_24) [custom_components.places.sensor] (place_samsung_p6800) End of Update

a bit later:

2023-09-30 03:21:00.179 INFO (SyncWorker_6) [custom_components.places.sensor] (place_samsung_p6800) Starting Track State Change Update (Tracked Entity: sensor.tracker_common_samsung_p6800)
2023-09-30 03:21:00.180 WARNING (SyncWorker_6) [custom_components.places.sensor] (place_samsung_p6800) Tracked Entity (sensor.tracker_common_samsung_p6800) Latitude/Longitude is not set or is not a number. Not Proceeding with Update.
2023-09-30 03:21:00.180 DEBUG (SyncWorker_6) [custom_components.places.sensor] (place_samsung_p6800) Tracked Entity (sensor.tracker_common_samsung_p6800) details: <state sensor.tracker_common_samsung_p6800=not_home; long_state=latitude=None, longitude=None, last_seen=1696032777.104532, place_source_type=router, place_source=iPhoneDetect, place=not_home, place_delta=8.1, place_alert=on, battery_level_source=Traccar, battery_level=1, battery_level_delta=8.1, battery_level_alert=on, battery_charging_source=Traccar, battery_charging=unavailable, battery_charging_delta=8.1, battery_charging_alert=on, place_formatted=Away, last_seen=2023-09-30T03:12:57.104532+03:00, latitude=None, longitude=None, source_type=router, place_source=iPhoneDetect, place=not_home, place_delta=8.1, place_alert=on, battery_level_source=Traccar, battery_level=1, battery_level_delta=8.1, battery_level_alert=on, battery_charging_source=Traccar, battery_charging=unavailable, battery_charging_delta=8.1, battery_charging_alert=on, entity_picture=/local/images/devices/samsung_p6800.png, friendly_name=Samsung P6800, icon=mdi:tablet @ 2023-09-30T03:15:05.695301+03:00>
2023-09-30 03:21:00.180 DEBUG (SyncWorker_6) [custom_components.places.sensor] (place_samsung_p6800) [is_devicetracker_set] proceed_with_update: 0
2023-09-30 03:21:00.180 DEBUG (SyncWorker_6) [custom_components.places.sensor] (place_samsung_p6800) Reverting attributes back to before the update started
2023-09-30 03:21:00.180 INFO (SyncWorker_6) [custom_components.places.sensor] (place_samsung_p6800) End of Update

Content of this entity: It has a long_state dictionary attribute and "exposed" attributes like latitude & longitude.

[Snuffy2]

So it looks like something is updating the sensor.tracker_common_samsung_p6800 even when it is offline. I say this because:

2023-09-30 03:17:00.180 INFO (SyncWorker_24) [custom_components.places.sensor] (place_samsung_p6800) Starting Track State Change Update (Tracked Entity: sensor.tracker_common_samsung_p6800)

2023-09-30 03:21:00.179 INFO (SyncWorker_6) [custom_components.places.sensor] (place_samsung_p6800) Starting Track State Change Update (Tracked Entity: sensor.tracker_common_samsung_p6800)

both indicate that the places update was triggered by the state or attributes of sensor.tracker_common_samsung_p6800 changing. That is why you are currently seeing the warning every minute.

I still need to find why the code is firing the warning every time instead of just the first time.

[ildar170975]

update was triggered by the state or attributes of sensor.tracker_common_samsung_p6800 changing

The entity is keep updating: for example, there are attributes like battery_level_delta which are redefined every minute (even when it may not be necessary). I am going to change this behaviour. So, if these constant updates are causing these warnings -> then this is (for me) expected behaviour. Yes, it may be optimized from your side like "do not repeat same warning"...

[Snuffy2]

So far, it actually looks like it is working "as currently designed." It is set to only fire the warning once if the places sensor has ever been set before. If it has never been set before, it will continue to fire as you are observing. I was trying to do something to alert users when a new places sensor wasn't working properly. I'm open to ideas or feedback but that's why it is currently setup this way.

[ildar170975]

Well, then we probably may close the issue... I found a problem in my sensor with lat/long - it keeps updating even when a device is unavailable, gonna fix it. Thank you for a support!