Hyundai-Kia-Connect / kia_uvo

A Home Assistant HACS integration that supports Kia Connect(Uvo) and Hyundai Bluelink. The integration supports the EU, Canada and the USA.
MIT License
421 stars 85 forks source link

Missing data due to communication errors and rate limit #874

Open johny-mnemonic opened 4 months ago

johny-mnemonic commented 4 months ago

EU - Hyundai Kona 2020

Version of the integration 2.24.2

Describe the bug For at least last few days I am having issues with car data vanishing from HA with sensors saying 'unavailable', etc.

I have seen random errors in the logs Error fetching kia_uvo data: Error communicating with API: Expecting value: line 1 column 1 (char 0) which roughly correlated with the missing data so I thought Hyundai servers are having issues and the integration is unable to handle it. So I created the automation to detect the data are missing and reload the integration in such case. It seemed to help at the first glance as I had data back after getting notification from that automation. I also got errors in the evening saying "Exceeds number of requests", so I edited all my automations which are able to call force update service (to have fresh data to control charging from PV) and either disabled those calls completely or changed those to normal update service calls. But none of my improvements seems to have improved the situation. Last two days even with the car mostly outside of the house (= no automations trying to refresh data from API) I got at least 5-6 notifications that data vanished from HA ( => integration got reloaded) and in the evening it stopped working completely due to the rate limit.

Today I enabled debug log and restarted HA around 17:04 and below is the result.

Debug logs if an error occurred

Short summary of the logs after debug enable ``` Restart HA to enable Kia UVO debug. 2024-05-06 17:04:12.041 DEBUG (MainThread) [custom_components.kia_uvo.coordinator] Finished fetching kia_uvo data in 6.970 seconds (success: False) 2024-05-06 17:04:36.905 DEBUG (MainThread) [custom_components.kia_uvo.coordinator] Finished fetching kia_uvo data in 5.433 seconds (success: False) 2024-05-06 17:04:52.538 DEBUG (MainThread) [custom_components.kia_uvo.coordinator] Finished fetching kia_uvo data in 5.394 seconds (success: False) 2024-05-06 17:05:19.525 DEBUG (MainThread) [custom_components.kia_uvo.coordinator] Finished fetching kia_uvo data in 6.591 seconds (success: False) 2024-05-06 17:06:04.879 DEBUG (MainThread) [custom_components.kia_uvo.coordinator] Finished fetching kia_uvo data in 5.275 seconds (success: False) 2024-05-06 17:07:31.242 DEBUG (MainThread) [custom_components.kia_uvo.coordinator] Finished fetching kia_uvo data in 6.198 seconds (success: False) Finally got data from API to sensors (even though all previous calls fetched them as well, but marked the fetch as "success: False") 2024-05-06 17:08:55.490 DEBUG (MainThread) [custom_components.kia_uvo.coordinator] Finished fetching kia_uvo data in 3.922 seconds (success: True) 2024-05-06 17:38:59.421 ERROR (MainThread) [custom_components.kia_uvo.coordinator] Error fetching kia_uvo data: Error communicating with API: Expecting value: line 1 column 1 (char 0) 2024-05-06 17:38:59.421 DEBUG (MainThread) [custom_components.kia_uvo.coordinator] Finished fetching kia_uvo data in 4.346 seconds (success: False) Data vanished from HA. 2024-05-06 17:40:05.714 DEBUG (MainThread) [custom_components.kia_uvo.coordinator] Finished fetching kia_uvo data in 6.275 seconds (success: False) 2024-05-06 17:40:24.131 DEBUG (SyncWorker_33) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - get_cached_vehicle_status response: {'retCode': 'F', 'resCode': '5031', 'resMsg': 'Unavailable remote control - Service Temporary Unavailable', 'msgId': 'b7322601-ed95-45da-93c2-6bf7eb7dfa73'} 2024-05-06 17:40:24.692 DEBUG (MainThread) [custom_components.kia_uvo.coordinator] Finished fetching kia_uvo data in 13.855 seconds (success: False) 2024-05-06 17:40:40.880 DEBUG (MainThread) [custom_components.kia_uvo.coordinator] Finished fetching kia_uvo data in 5.708 seconds (success: False) 2024-05-06 17:41:07.568 DEBUG (MainThread) [custom_components.kia_uvo.coordinator] Finished fetching kia_uvo data in 6.280 seconds (success: False) 2024-05-06 17:42:00.403 DEBUG (SyncWorker_24) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - get_cached_vehicle_status response: {'retCode': 'F', 'resCode': '5031', 'resMsg': 'Unavailable remote control - Service Temporary Unavailable', 'msgId': '25f8a99b-12cf-458c-b2d6-3033439419f7'} 2024-05-06 17:42:00.403 DEBUG (MainThread) [custom_components.kia_uvo.coordinator] Finished fetching kia_uvo data in 12.407 seconds (success: False) 2024-05-06 17:43:27.045 DEBUG (MainThread) [custom_components.kia_uvo.coordinator] Finished fetching kia_uvo data in 6.191 seconds (success: False) 2024-05-06 17:44:53.845 DEBUG (MainThread) [custom_components.kia_uvo.coordinator] Finished fetching kia_uvo data in 6.357 seconds (success: False) 2024-05-06 17:46:20.271 DEBUG (MainThread) [custom_components.kia_uvo.coordinator] Finished fetching kia_uvo data in 6.237 seconds (success: False) 2024-05-06 17:47:46.926 DEBUG (MainThread) [custom_components.kia_uvo.coordinator] Finished fetching kia_uvo data in 6.235 seconds (success: False) 2024-05-06 17:49:10.350 DEBUG (SyncWorker_32) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - get_driving_info response30d {'retCode': 'F', 'resCode': '5091', 'resMsg': 'Exceeds number of requests - Exceeds Number of Requests.', 'msgId': '8cfcbc0d-a197-4def-b810-27bc338b7eb8'} 2024-05-06 17:49:10.350 ERROR (SyncWorker_32) [hyundai_kia_connect_api.KiaUvoApiEU] Failed to parse driving info. Possible reasons: - incompatible vehicle (ICE) - new API format - API outage Traceback (most recent call last): File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/KiaUvoApiEU.py", line 343, in update_vehicle_with_cached_state state = self._get_driving_info(token, vehicle) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/KiaUvoApiEU.py", line 1074, in _get_driving_info _check_response_for_errors(response30d) File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/KiaUvoApiEU.py", line 126, in _check_response_for_errors raise error_code_mapping[response["resCode"]](response["resMsg"]) hyundai_kia_connect_api.exceptions.RateLimitingError: Exceeds number of requests - Exceeds Number of Requests. 2024-05-06 17:49:10.608 DEBUG (SyncWorker_23) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - get_cached_vehicle_status response: {'retCode': 'F', 'resCode': '5091', 'resMsg': 'Exceeds number of requests - Exceeds Number of Requests.', 'msgId': 'f79fe9c9-532c-436d-befd-960248bcbdc4'} 2024-05-06 17:49:10.609 DEBUG (MainThread) [custom_components.kia_uvo.coordinator] Finished fetching kia_uvo data in 3.392 seconds (success: False) ```

It seems to me as if the integration is having trouble to authenticate and fetch the data. After HA restart with the debug it successfully authenticated and downloaded data from API multiple times but it always reported it as success: False, which is weird.

Log from first data fetch after HA restart This one and five following ones all had data without any issue that I could see at first glance, but were all reported as unsuccessful by the integration. ``` 2024-05-06 17:04:05.071 DEBUG (SyncWorker_12) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - Get Device ID request 2024-05-06 17:04:06.173 DEBUG (SyncWorker_12) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - Get Device ID response: {'retCode': 'S', 'resCode': '0000', 'resMsg': {'deviceId': 'cb834003-f51a-41d9-b10d-02dd5630a757'}, 'msgId': '4c5c40ac-767c-45ea-88c9-568484af8c22'} 2024-05-06 17:04:06.173 DEBUG (SyncWorker_12) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - Get cookies request: https://prd.eu-ccapi.hyundai.com:8080/api/v1/user/oauth2/authorize?response_type=code&state=test&client_id=XXXXXX-YYYY-4cf3-9557-ZZZZZZ&redirect_uri=https://prd.eu-ccapi.hyundai.com:8080/api/v1/user/oauth2/redirect&lang=cs 2024-05-06 17:04:06.316 DEBUG (SyncWorker_12) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - Get cookies response: {'account': 'XXX.aaa', 'TS0144b999': 'xxxxx'} 2024-05-06 17:04:06.578 DEBUG (SyncWorker_12) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - Sign In Response: {'errId': 'c6c712f3-7943-4d63-b192-e4310cd97d26', 'errCode': '4003', 'errMsg': 'Invalid values'} 2024-05-06 17:04:06.578 DEBUG (SyncWorker_12) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - get_authorization_code_with_redirect_url failed 2024-05-06 17:04:06.680 DEBUG (SyncWorker_12) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - IntegrationInfo Response: {'userId': 'aaaaaaa-1264-4f6e-9ddf-00000000', 'serviceId': 'XXXXXX-YYYY-4cf3-9557-ZZZZZZ', 'serviceName': 'Bluelink'} 2024-05-06 17:04:07.142 DEBUG (SyncWorker_12) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - LoginForm https://eu-account.hyundai.com/auth/realms/euhyundaiidm/protocol/openid-connect/auth?client_id=64621b96-0f0d-11ec-82a8-0242ac130003&scope=openid%20profile%20email%20phone&response_type=code&hkid_session_reset=true&redirect_uri=https://prd.eu-ccapi.hyundai.com:8080/api/v1/user/integration/redirect/login&ui_locales=cs&state=XXXXXX-YYYY-4cf3-9557-ZZZZZZ:XXXXXX-YYYY-ZZZZZZ - Response: 2024-05-06 17:04:07.356 DEBUG (SyncWorker_12) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - LoginFormSubmit https://eu-account.hyundai.com/auth/realms/euhyundaiidm/login-actions/authenticate?session_code=aaaXXX&execution=xxxAAA&client_id=XXX&tab_id=ZZZ - Response 302 - {'Date': 'Mon, 06 May 2024 15:04:07 GMT', 'Content-Length': '0', 'Connection': 'keep-alive', 'Cache-Control': 'no-store, must-revalidate, max-age=0', 'Set-Cookie': 'KEYCLOAK_LOCALE=cs; Version=1; Path=/auth/realms/euhyundaiidm/; HttpOnly, KC_RESTART=; Version=1; Expires=Thu, 01-Jan-1970 00:00:10 GMT; Max-Age=0; Path=/auth/realms/euhyundaiidm/; HttpOnly, .............. 2024-05-06 17:04:07.664 DEBUG (SyncWorker_12) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - Redirect User Id 2024-05-06 17:04:07.891 DEBUG (SyncWorker_12) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - silentsignin Response {'redirectUrl': 'https://prd.eu-ccapi.hyundai.com:8080/api/v1/user/oauth2/redirect?code=ELNXXX-XXX_UUU&state=test', 'popup': False, 'method': '', 'upgrade': False, 'integrated': False, 'deleteAccountLink': ''} 2024-05-06 17:04:07.891 DEBUG (SyncWorker_12) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - Get Access Token Data: {'Authorization': 'Basic XXXXXX==', 'Stamp': 'XXXxxx/XXX=', 'Content-type': 'application/x-www-form-urlencoded', 'Host': 'prd.eu-ccapi.hyundai.com:8080', 'Connection': 'close', 'Accept-Encoding': 'gzip, deflate', 'User-Agent': 'okhttp/3.12.0'}grant_type=authorization_code&redirect_uri=https%3A%2F%2Fprd.eu-ccapi.hyundai.com%3A8080%2Fapi%2Fv1%2Fuser%2Foauth2%2Fredirect&code=ELNXXX-XXX_UUU 2024-05-06 17:04:08.015 DEBUG (SyncWorker_12) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - Get Access Token Response: {'access_token': 'XXX.ZZZ.ZZ-ZZ-XXX-XXX-XXX-XXX', 'token_type': 'Bearer', 'refresh_token': 'XXXZZZXXX', 'expires_in': 86400} 2024-05-06 17:04:08.015 DEBUG (SyncWorker_12) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - Access Token Value Bearer 2024-05-06 17:04:08.015 DEBUG (SyncWorker_12) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - Get Refresh Token Data: grant_type=refresh_token&redirect_uri=https%3A%2F%2Fwww.getpostman.com%2Foauth2%2Fcallback&refresh_token=ELNXXX-XXX_UUU 2024-05-06 17:04:08.139 DEBUG (SyncWorker_12) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - Get Refresh Token Response: {'access_token': 'XXXXXX', 'token_type': 'Bearer', 'expires_in': 86400} 2024-05-06 17:04:08.306 DEBUG (SyncWorker_12) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - Get Vehicles Response: {'retCode': 'S', 'resCode': '0000', 'resMsg': {'vehicles': [{'vin': .......}]}, 'msgId': '42c35ac8-9812-42aa-a23a-5a1930853ecb'} 2024-05-06 17:04:08.582 DEBUG (SyncWorker_17) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - get_cached_vehicle_status response: {'retCode': 'S', 'resCode': '0000', 'resMsg': {'vehicleStatusInfo': .........}, 'msgId': '6d7d6b01-6316-41d8-8d38-9343e54d5d1d'} 2024-05-06 17:04:08.769 DEBUG (SyncWorker_17) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - get_driving_info responseAlltime {'retCode': 'S', 'resCode': '0000', 'resMsg': {'drivingInfo': .......}, 'msgId': 'ea625655-ecb4-4d40-95a6-7a335ddffdc7'} 2024-05-06 17:04:08.920 DEBUG (SyncWorker_17) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - get_driving_info response30d {'retCode': 'S', 'resCode': '0000', 'resMsg': {'drivingInfo': ........}, 'msgId': '2e62e770-5c15-4fd1-939b-5e3d69604dfa'} 2024-05-06 17:04:08.922 DEBUG (SyncWorker_17) [hyundai_kia_connect_api.KiaUvoApiEU] KiaUvoApiEU: before daily_stats: [DailyDrivingStats(date=datetime.datetime(2024, 5, 6, 0, 0) 2024-05-06 17:04:08.922 DEBUG (SyncWorker_17) [hyundai_kia_connect_api.KiaUvoApiEU] KiaUvoApiEU: after daily_stats: [DailyDrivingStats(date=datetime.datetime(2024, 5, 6, 0, 0) 2024-05-06 17:04:09.191 DEBUG (SyncWorker_13) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - get_cached_vehicle_status response: {'retCode': 'S', 'resCode': '0000', 'resMsg': {'vehicleStatusInfo': ...........}, 'msgId': '34d6fb1a-e4c5-4081-85a5-392f1ec1bb75'} 2024-05-06 17:04:09.394 DEBUG (SyncWorker_13) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - get_driving_info responseAlltime {'retCode': 'S', 'resCode': '0000', 'resMsg': {'drivingInfo':.......}, 'msgId': '6a61bc89-e9a0-46ae-a14a-d6f68dd263ce'} 2024-05-06 17:04:09.544 DEBUG (SyncWorker_13) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - get_driving_info response30d {'retCode': 'S', 'resCode': '0000', 'resMsg': {'drivingInfo':.......}, 'msgId': 'f63dcbd0-359e-4612-833b-0ca9c2127bb4'} 2024-05-06 17:04:09.545 DEBUG (SyncWorker_13) [hyundai_kia_connect_api.KiaUvoApiEU] KiaUvoApiEU: before daily_stats: [DailyDrivingStats(date=datetime.datetime(2024, 5, 6, 0, 0) 2024-05-06 17:04:09.545 DEBUG (SyncWorker_13) [hyundai_kia_connect_api.KiaUvoApiEU] KiaUvoApiEU: after daily_stats: [DailyDrivingStats(date=datetime.datetime(2024, 5, 6, 0, 0) 2024-05-06 17:04:12.041 DEBUG (MainThread) [custom_components.kia_uvo.coordinator] Finished fetching kia_uvo data in 6.970 seconds (success: False) ```

Could it be that the integration is retrying the data fetch so often (due to marking in unsuccessful) that it triggers the rate limit on Hyundai side?

I am not sure if I read the logs correctly but it looks to me like it is doing full authentication for each fetch instead of using the token till it expires. At least that's how I understand following log lines, which are always followed by the full login form and new token generation.

2024-05-06 17:04:32.069 DEBUG (SyncWorker_4) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - Sign In Response: {'errId': 'd91a035a-09b6-407b-826e-6419efd76f33', 'errCode': '4003', 'errMsg': 'Invalid values'}
2024-05-06 17:04:32.069 DEBUG (SyncWorker_4) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - get_authorization_code_with_redirect_url failed

Not sure if it contributes to the problem or if it is harmless.

Expected behavior I am using the integration since last November and it was mostly smooth sailing. Thanks! I just had 2-3 times an issue with rate limit when I was developing the automation for the charging control and triggered the force update too many times. So I wonder what has changed that it started to have these issues.

ScratMan commented 4 months ago

Same issue here.

After a restart this morning, got this error:

Cette erreur provient d'une intégration personnalisée

Enregistreur: custom_components.kia_uvo.coordinator
Source: custom_components/kia_uvo/coordinator.py:126
intégration: Hyundai / Kia Connect (documentation, problèmes)
S'est produit pour la première fois: 07:11:45 (1 occurrences)
Dernier enregistrement: 07:11:45

Force update failed, falling back to cached: Expecting value: line 1 column 1 (char 0)
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/requests/models.py", line 971, in json
    return complexjson.loads(self.text, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/simplejson/__init__.py", line 514, in loads
    return _default_decoder.decode(s)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/simplejson/decoder.py", line 386, in decode
    obj, end = self.raw_decode(s)
               ^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/simplejson/decoder.py", line 416, in raw_decode
    return self.scan_once(s, idx=_w(s, idx).end())
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
simplejson.errors.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/config/custom_components/kia_uvo/coordinator.py", line 126, in _async_update_data
    await self.hass.async_add_executor_job(
  File "/usr/local/lib/python3.12/concurrent/futures/thread.py", line 58, in run
    result = self.fn(*self.args, **self.kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/VehicleManager.py", line 110, in check_and_force_update_vehicles
    self.update_vehicle_with_cached_state(vehicle_id)
  File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/VehicleManager.py", line 87, in update_vehicle_with_cached_state
    self.api.update_geocoded_location(
  File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/ApiImpl.py", line 95, in update_geocoded_location
    response = response.json()
               ^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/requests/models.py", line 975, in json
    raise RequestsJSONDecodeError(e.msg, e.doc, e.pos)
requests.exceptions.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

And then some other arrived later on today

Cette erreur provient d'une intégration personnalisée

Enregistreur: custom_components.kia_uvo.coordinator
Source: helpers/update_coordinator.py:347
intégration: Hyundai / Kia Connect (documentation, problèmes)
S'est produit pour la première fois: 07:41:49 (3 occurrences)
Dernier enregistrement: 09:21:47

Error fetching kia_uvo data: Error communicating with API: Expecting value: line 1 column 1 (char 0)
Enregistreur: hyundai_kia_connect_api.KiaUvoApiEU
Source: /usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/KiaUvoApiEU.py:348
S'est produit pour la première fois: 09:35:50 (1 occurrences)
Dernier enregistrement: 09:35:50

Failed to parse driving info. Possible reasons: - incompatible vehicle (ICE) - new API format - API outage
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/KiaUvoApiEU.py", line 343, in update_vehicle_with_cached_state
    state = self._get_driving_info(token, vehicle)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/KiaUvoApiEU.py", line 1065, in _get_driving_info
    _check_response_for_errors(responseAlltime)
  File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/KiaUvoApiEU.py", line 126, in _check_response_for_errors
    raise error_code_mapping[response["resCode"]](response["resMsg"])
hyundai_kia_connect_api.exceptions.RateLimitingError: Exceeds number of requests - Exceeds Number of Requests.
Cette erreur provient d'une intégration personnalisée

Enregistreur: custom_components.kia_uvo.coordinator
Source: helpers/update_coordinator.py:315
intégration: Hyundai / Kia Connect (documentation, problèmes)
S'est produit pour la première fois: 09:37:14 (160 occurrences)
Dernier enregistrement: 13:08:11

Unexpected error fetching kia_uvo data
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 315, in _async_refresh
    self.data = await self._async_update_data()
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/kia_uvo/coordinator.py", line 107, in _async_update_data
    await self.async_check_and_refresh_token()
  File "/config/custom_components/kia_uvo/coordinator.py", line 166, in async_check_and_refresh_token
    await self.hass.async_add_executor_job(
  File "/usr/local/lib/python3.12/concurrent/futures/thread.py", line 58, in run
    result = self.fn(*self.args, **self.kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/VehicleManager.py", line 125, in check_and_refresh_token
    self.initialize()
  File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/VehicleManager.py", line 71, in initialize
    vehicles = self.api.get_vehicles(self.token)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/KiaUvoApiEU.py", line 271, in get_vehicles
    _check_response_for_errors(response)
  File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/KiaUvoApiEU.py", line 126, in _check_response_for_errors
    raise error_code_mapping[response["resCode"]](response["resMsg"])
hyundai_kia_connect_api.exceptions.RateLimitingError: Exceeds number of requests - Exceeds Number of Requests.
busywait commented 4 months ago

Me too, I think. I saw the "rate limit" error logged exactly once for the first time this week. It left a one-hour gap in the data, and does seem to be a change in behaviour. In the past I accidentally had forced updates running in tight loop for most of an hour, and there was no lock-out.

Edit: I have the "scan interval" (web api cache updates) set to 15, and "force refresh interval" set to 9999. I trigger force refresh via the service call every 12 minutes during some long journeys, at the end of every journey, and when my home charger detects that it has been plugged in or unplugged.

peter4200 commented 4 months ago

I have the same problem Hyundai Ioniq 5

cdnninja commented 4 months ago

Just to confirm when you mention same issue. Do you mean the login error or rate limit? If rate limit adjust your settings down for force update and see if that helps. If not try lower regular update interval too.

peter4200 commented 4 months ago

Just to confirm when you mention same issue. Do you mean the login error or rate limit? If rate limit adjust your settings down for force update and see if that helps. If not try lower regular update interval too.

D'oh - sorry I have tried to adjust my setting and will keep an eye on the log file

Taomyn commented 4 months ago

I've been getting the same issue and logged messages as the OP for over a week now - I was hoping this was a transient issue at Hyundai (EU) but obviously not. I have cached scans at 30min and forced at 1440min, and I get alerted to the problem approximately every 2 hours.

jsuanet commented 4 months ago

Also getting the "Error fetching kia_uvo data: Error communicating with API: Expecting value: line 1 column 1 (char 0)" error. After several reloads of the integration it works for some hours and then the entities become unavailable again. In the HA logs:

Logger: homeassistant.components.websocket_api.http.connection Source: components/websocket_api/commands.py:239 integration: Home Assistant WebSocket API (documentation, issues) First occurred: 12:14:36 (1 occurrences) Last logged: 12:14:36

[546754315968] Unexpected exception Traceback (most recent call last): File "/usr/local/lib/python3.12/site-packages/requests/models.py", line 971, in json return complexjson.loads(self.text, **kwargs) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/simplejson/init.py", line 514, in loads return _default_decoder.decode(s) ^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/simplejson/decoder.py", line 386, in decode obj, end = self.raw_decode(s) ^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/simplejson/decoder.py", line 416, in raw_decode return self.scan_once(s, idx=_w(s, idx).end()) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ simplejson.errors.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

During handling of the above exception, another exception occurred:

Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 239, in handle_call_service response = await hass.services.async_call( ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/core.py", line 2738, in async_call response_data = await coro ^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/core.py", line 2779, in _execute_service return await target(service_call) ^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/config/custom_components/kia_uvo/services.py", line 54, in async_handle_update await coordinator.async_update_all() File "/config/custom_components/kia_uvo/coordinator.py", line 151, in async_update_all await self.hass.async_add_executor_job( File "/usr/local/lib/python3.12/concurrent/futures/thread.py", line 58, in run result = self.fn(*self.args, **self.kwargs) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/VehicleManager.py", line 80, in update_all_vehicles_with_cached_state self.update_vehicle_with_cached_state(vehicle_id) File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/VehicleManager.py", line 87, in update_vehicle_with_cached_state self.api.update_geocoded_location( File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/ApiImpl.py", line 95, in update_geocoded_location response = response.json() ^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/requests/models.py", line 975, in json raise RequestsJSONDecodeError(e.msg, e.doc, e.pos) requests.exceptions.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

johny-mnemonic commented 4 months ago

Just to confirm when you mention same issue. Do you mean the login error or rate limit? If rate limit adjust your settings down for force update and see if that helps. If not try lower regular update interval too.

@cdnninja I am afraid the rate limit is just the result of the issue (all those retries simply trigger the rate limit on the Hyundai side).

I have tried to completely disable refreshing the data in the integration and also in my automations so anytime I need an update I need to call the update service. It looked promising for almost two days. It behaved the way that after restart of HA it fetched data successfully on the first try and then it also got the data every time I called the force update.

But seems like it was just a coincidence as few hours ago I called force update, resulting in loosing the data in HA for almost 8 minutes. When I checked the logs it indeed ended in the same "retry loop" where every fetch downloaded the data from the API, but marked the fetch as unsuccessful ( Finished fetching kia_uvo data in 10.395 seconds (success: False) ) and retried the fetch in roughly 70-80s while doing whole reauthentication again (instead of reusing the auth token). It is weird, that there are always 7 retries till it finally marks the fetch as success (success: True) after the failure with that Expecting value: line 1 column 1 (char 0) error.

I think we need to find whether there really is some issue with Hyundai servers (i.e. not returning complete data) or whether there was some bug introduced in the integration. The rate limit is not interesting as it is caused by the integration frequently asking the API again and again for the same data...

cdnninja commented 4 months ago

It's odd that your first set of debug data only has kia_uvo and no api data. Did you filter that?

johny-mnemonic commented 4 months ago

Enabling debug logs is next step.

I have it enabled. That's how I am able to see these logs. They are not visible without the debug enabled. I enabled it before reporting this issue here to see what is going on.

Not sure what do you mean by missing api data. If you check the log under the "Log from first data fetch after HA restart" it is almost exclusively api data (hyundai_kia_connect_api.KiaUvoApiEU). But you are correct, that I filtered a lot of data as the log is huge and containing data specific to my car and IDs. I can share full log privately if it helps.

Boscdam commented 4 months ago

I will share my thoghuts, after reading some of the comments. I created an automatation that is asking a force update every 60 min, that is lower than the value on the integration. Doing in that way, I am not having an unavailable data, at least in last 48h. I havent restarted HA yet.

cdnninja commented 4 months ago

For some cars that may drain your battery.

johny-mnemonic commented 4 months ago

@Boscdam I had been doing this for months before the current issues started and never had an issue, but now it depletes the number of connections due to retries and you get rate limited. Also as @cdnninja points out, you are risking to drain your 12V battery completely, so I have an condition in the automation to only do the force update every 60 minutes when the car is connected to the charger. If not I just rely on the integration to update it once in 6 hours.

johny-mnemonic commented 4 months ago

I have another possibly interesting observation.

I left the integration alone without any single update request for 3 days (with auto-updates disabled) and I can confirm there was not a single line in the log from the integration. When I then tried to do the standard update calls (without force) it was always failing with the error below:

2024-05-16 14:42:36.183 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [140562972061376] Unexpected exception
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/requests/models.py", line 971, in json
    return complexjson.loads(self.text, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/simplejson/__init__.py", line 514, in loads
    return _default_decoder.decode(s)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/simplejson/decoder.py", line 386, in decode
    obj, end = self.raw_decode(s)
               ^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/simplejson/decoder.py", line 416, in raw_decode
    return self.scan_once(s, idx=_w(s, idx).end())
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
simplejson.errors.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 239, in handle_call_service
    response = await hass.services.async_call(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2738, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2779, in _execute_service
    return await target(service_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/kia_uvo/services.py", line 54, in async_handle_update
    await coordinator.async_update_all()
  File "/config/custom_components/kia_uvo/coordinator.py", line 151, in async_update_all
    await self.hass.async_add_executor_job(
  File "/usr/local/lib/python3.12/concurrent/futures/thread.py", line 58, in run
    result = self.fn(*self.args, **self.kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/VehicleManager.py", line 80, in update_all_vehicles_with_cached_state
    self.update_vehicle_with_cached_state(vehicle_id)
  File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/VehicleManager.py", line 87, in update_vehicle_with_cached_state
    self.api.update_geocoded_location(
  File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/ApiImpl.py", line 95, in update_geocoded_location
    response = response.json()
               ^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/requests/models.py", line 975, in json
    raise RequestsJSONDecodeError(e.msg, e.doc, e.pos)
requests.exceptions.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

As reported previously, looking at the debug log it seems like all the fetches I have done were actually successful. At least I can see the authentication worked, it got the data from API (hyundai_kia_connect_api - get_cached_vehicle_status and hyundai_kia_connect_api - get_driving_info response30d) and it updated daily_stats. So the log looks exactly the same as the one from the fetches ending with Finished fetching kia_uvo data in 4.926 seconds (success: True) 🤯

I finally gave up and restarted HA after which it started working again.

Looks to me like an issue with parsing some part of the API response which is not even related to the data used for the HA as all of that data seems to be parsed successfully before it fails on that decoding error.

cdnninja commented 4 months ago

Are you sure debug is enabled?

Also a new api just had a bug fix that may help here. I haven't put this version to the integration yet.

johny-mnemonic commented 4 months ago

@cdnninja I am pretty sure. At least my log contains lines like below and those in OP:

2024-05-16 14:42:35.077 DEBUG (MainThread) [custom_components.kia_uvo.services] Call:{}
2024-05-16 14:42:35.803 DEBUG (SyncWorker_29) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - get_cached_vehicle_status response: {...
2024-05-16 14:42:36.091 DEBUG (SyncWorker_29) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - get_driving_info response30d {...
2024-05-16 14:42:36.092 DEBUG (SyncWorker_29) [hyundai_kia_connect_api.KiaUvoApiEU] KiaUvoApiEU: before daily_stats: [DailyDrivingStats(...
2024-05-16 14:42:36.093 DEBUG (SyncWorker_29) [hyundai_kia_connect_api.KiaUvoApiEU] KiaUvoApiEU: after  daily_stats: [DailyDrivingStats...
2024-05-16 14:42:36.183 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [140562972061376] Unexpected exception
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/requests/models.py", line 971, in json
    return complexjson.loads(self.text, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/simplejson/__init__.py", line 514, in loads
    return _default_decoder.decode(s)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/simplejson/decoder.py", line 386, in decode
    obj, end = self.raw_decode(s)
               ^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/simplejson/decoder.py", line 416, in raw_decode
    return self.scan_once(s, idx=_w(s, idx).end())
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
simplejson.errors.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

I believe all of the lines except the error are only there because I have enabled the debug.

Would you create a new version with the api bugfix? Or give some instructions how to manually add it to the installed integration?

cdnninja commented 4 months ago

I just bumped the API in the manifest file. Could you try update to the "master" branch and let me know if it fixes it?

johny-mnemonic commented 4 months ago

@cdnninja I don't want to jinx it, but so far so good. No errors, no re-authentications and every fetch request ends with (success: True). So seems like there really was some API change or fix needed. Looking at the changes in the hyundai_kia_connect_api there are a lot of auth related changes in last commit, so it looks like the auth itself was the issue...

popy2k14 commented 4 months ago

@johny-mnemonic and of course @cdnninja Any chance to get this merged soon? Having those issues (entities unavailable) for a few weeks now.

cdnninja commented 4 months ago

It is now released.

jsuanet commented 4 months ago

When I install this version (V2.24.3) via HACS I get the following error in HA

Logger: homeassistant.util.package Source: util/package.py:123 First occurred: 16:59:51 (3 occurrences) Last logged: 17:00:08

Unable to install package hyundai_kia_connect_api==3.20.1: ERROR: Could not find a version that satisfies the requirement hyundai_kia_connect_api==3.20.1 (from versions: 0.1.0, 0.1.1, 0.1.2, 0.1.3, 0.1.4, 1.2.0, 1.3.0, 1.4.0, 1.5.0, 1.6.0, 1.7.0, 1.7.1, 1.7.2, 1.7.3, 1.7.4, 1.8.0, 1.8.1, 1.8.2, 1.10.1, 1.10.2, 1.10.4, 1.11.0, 1.12.0, 1.12.1, 1.14.0, 1.14.1, 1.14.2, 1.14.3, 1.14.4, 1.17.1, 1.17.3, 1.18.7, 1.18.8, 1.18.10, 1.18.11, 1.18.12, 1.18.13, 1.18.14, 1.18.15, 1.18.16, 1.18.17, 1.18.18, 1.19.0, 1.19.1, 1.19.2, 1.19.3, 1.19.4, 1.19.5, 1.19.6, 1.19.7, 1.19.8, 1.19.9, 1.19.10, 1.20.0, 1.21.0, 1.21.1, 1.21.2, 1.21.3, 1.21.4, 1.21.5, 1.21.6, 1.21.7, 1.22.0, 1.22.1, 1.22.2, 1.22.3, 1.22.4, 1.22.5, 1.22.6, 1.22.7, 1.22.8, 1.22.9, 1.23.0, 1.23.1, 1.24.0, 1.25.0, 1.26.0, 1.26.1, 1.26.2, 1.26.3, 1.26.4, 1.26.5, 1.27.0, 1.27.1, 1.28.0, 1.28.1, 1.28.2, 1.28.3, 1.28.4, 1.28.5, 1.29.0, 1.29.1, 1.29.2, 1.29.3, 1.30.0, 1.31.0, 1.32.0, 1.33.0, 1.34.0, 1.34.1, 1.34.2, 1.34.3, 1.34.4, 1.34.5, 1.34.6, 1.34.7, 1.34.8, 1.34.9, 1.35.0, 1.35.1, 1.35.2, 1.35.3, 1.35.4, 1.35.5, 1.36.0, 1.36.1, 1.36.2, 1.36.3, 1.36.4, 1.36.5, 1.36.6, 1.36.7, 1.36.8, 1.36.9, 1.36.10, 1.36.11, 1.36.12, 1.37.0, 1.37.1, 1.37.2, 1.37.3, 1.37.4, 1.37.5, 1.37.6, 1.37.7, 1.37.8, 1.37.9, 1.37.10, 1.38.0, 1.39.0, 1.39.1, 1.39.2, 1.39.3, 1.39.4, 1.39.5, 1.39.6, 1.39.7, 1.40.0, 1.40.1, 1.40.2, 1.40.3, 1.40.4, 1.40.5, 1.40.6, 1.40.7, 1.40.8, 1.40.9, 1.40.10, 1.40.11, 1.40.12, 1.40.13, 1.41.0, 1.41.1, 1.41.2, 1.41.3, 1.41.4, 1.42.0, 1.42.1, 1.42.2, 1.42.3, 1.42.4, 1.42.5, 1.43.0, 1.43.1, 1.43.2, 1.43.3, 1.44.0, 1.44.1, 1.44.2, 1.44.3, 1.44.4, 1.45.0, 1.45.1, 1.45.2, 1.45.3, 1.45.4, 1.45.5, 1.45.6, 1.46.0, 1.47.0, 1.47.1, 1.47.2, 1.47.3, 1.50.3, 1.51.0, 1.51.1, 1.52.0, 1.52.1, 1.52.2, 1.52.3, 1.52.4, 1.52.5, 1.52.6, 1.52.7, 1.52.8, 1.52.9, 1.52.10, 1.52.11, 1.52.12, 1.52.13, 1.53.0, 1.53.1, 1.53.2, 2.0.0, 2.0.1, 2.0.2, 2.1.0, 2.1.1, 2.1.2, 2.2.0, 2.3.0, 2.3.1, 2.3.2, 2.3.3, 2.4.0, 2.4.1, 2.4.2, 2.4.3, 2.4.4, 3.0.0, 3.1.0, 3.1.1, 3.1.2, 3.1.3, 3.1.6, 3.1.7, 3.1.8, 3.1.9, 3.1.10, 3.2.0, 3.3.0, 3.3.1, 3.3.2, 3.3.3, 3.3.4, 3.3.5, 3.3.6, 3.3.7, 3.3.8, 3.3.9, 3.3.10, 3.3.11, 3.3.12, 3.3.13, 3.4.0, 3.5.0, 3.6.0, 3.7.0, 3.8.0, 3.8.1, 3.8.2, 3.8.3, 3.8.4, 3.8.5, 3.8.6, 3.9.0, 3.9.1, 3.10.0, 3.10.1, 3.10.2, 3.10.3, 3.10.4, 3.10.5, 3.10.6, 3.10.7, 3.10.8, 3.10.9, 3.10.10, 3.10.11, 3.10.12, 3.11.0, 3.11.1, 3.11.2, 3.11.3, 3.11.4, 3.12.0, 3.13.0, 3.13.1, 3.13.2, 3.14.0, 3.14.1, 3.14.2, 3.14.3, 3.15.0, 3.15.1, 3.16.0, 3.17.0, 3.17.1, 3.17.2, 3.17.3, 3.17.4, 3.17.5, 3.17.6, 3.17.7, 3.17.8, 3.17.9, 3.17.10, 3.18.0, 3.19.0, 3.19.1) ERROR: No matching distribution found for hyundai_kia_connect_api==3.20.1

johny-mnemonic commented 4 months ago

@cdnninja I am afraid I had jinxed it. With the new API lib there are no re-auths and the data seems to not be vanishing from the HA when doing regular updates. But the error is still there at the end of some of the fetches:

2024-05-20 16:14:57.627 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [140213767006528] Unexpected exception
Traceback (most recent call last):
File "/usr/local/lib/python3.12/site-packages/requests/models.py", line 971, in json
return complexjson.loads(self.text, **kwargs)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/simplejson/__init__.py", line 514, in loads
return _default_decoder.decode(s)
^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/simplejson/decoder.py", line 386, in decode
obj, end = self.raw_decode(s)
^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/simplejson/decoder.py", line 416, in raw_decode
return self.scan_once(s, idx=_w(s, idx).end())
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
simplejson.errors.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

I hoped it might be unrelated to the data vanishing from HA, but I now tried to also do a force update and it ended with the json parsing error as well and all the data vanished from HA 😢 Reloading the integration ended in the same retry loop like before where every fetch do the auth successfully and seemingly downloads all the data, but ends with (success: False), so the integration is not even able to initialize. Will probably try to restart HA to see if it breaks the retry loop. Otherwise it will trigger the rate limit...

EDIT: After 15 unsuccessful fetches the 16th ended with success and I have the data back.

cdnninja commented 4 months ago

I broke something on the release. I'll fix when home.

cdnninja commented 4 months ago

Please try the latest again.

popy2k14 commented 4 months ago

Installed new version late yesterday and working until now. Thx

jsuanet commented 4 months ago

Unfortunately still getting below error after upgrade to version V2.24.4

This error originated from a custom integration.

Logger: custom_components.kia_uvo.coordinator Source: helpers/update_coordinator.py:347 integration: Kia Uvo / Hyundai Bluelink (documentation, issues) First occurred: 07:58:36 (3 occurrences) Last logged: 09:36:34

Error fetching kia_uvo data: Error communicating with API: Expecting value: line 1 column 1 (char 0)

popy2k14 commented 4 months ago

Same issue after a few hours again, all entities are unavailable.

robyholmes commented 4 months ago

Just started using this integration and it's been fine for a few days, then suddenly today it's erroring with entities being unavailable. Restarting the integration brings it back for 30 minutes until the next refresh.

johny-mnemonic commented 4 months ago

@robyholmes yeah, unfortunately it is broken for a few weeks now. I would recommend disabling the refresh in the integration completely and only call the force update manually or from some automation when you need the fresh data. You can also try normal updates before the forced one. They sometimes work, but everything is hit or miss now 😞

robyholmes commented 4 months ago

@robyholmes yeah, unfortunately it is broken for a few weeks now. I would recommend disabling the refresh in the integration completely and only call the force update manually or from some automation when you need the fresh data. You can also try normal updates before the forced one. They sometimes work, but everything is hit or miss now 😞

Shame when it's been working fine. How do you disable the cache update? I set it to 999 minutes but it's still erroring within a few minutes of a force update.

johny-mnemonic commented 4 months ago

@robyholmes In the integration you click those three dots and open system options, where you can disable the updating completely.

robyholmes commented 4 months ago

@robyholmes In the integration you click those three dots and open system options, where you can disable the updating completely.

Thank you. Found it!

popy2k14 commented 4 months ago

Any workaround for this issue?

Love the integration, sadly all entities are unavailable most of the time.

johny-mnemonic commented 1 month ago

@cdnninja would it be possible to add debug output for the failing step (json decoder)? I think it would help us to see what kind of json is on it's input and why it complains that there is nothing on line 1 column 1 (char 0) position.

cdnninja commented 1 month ago

I tried to improve some logging. Could you update to latest and see if logs have more detail?

dagobert commented 1 month ago

I installed the master version and get the following error: Logger: custom_components.kia_uvo.coordinator Quelle: helpers/update_coordinator.py:386 Integration: Hyundai / Kia Connect ([Dokumentation](https://github.com/Hyundai-Kia-Connect/kia_uvo), [Probleme](https://github.com/Hyundai-Kia-Connect/kia_uvo/issues)) Erstmals aufgetreten: 09:50:13 (1 Vorkommnisse) Zuletzt protokolliert: 09:50:13 Error fetching kia_uvo data: Error communicating with API: Traceback (most recent call last): File "/usr/local/lib/python3.12/site-packages/requests/models.py", line 974, in json return complexjson.loads(self.text, **kwargs) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/simplejson/__init__.py", line 514, in loads return _default_decoder.decode(s) ^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/simplejson/decoder.py", line 386, in decode obj, end = self.raw_decode(s) ^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/simplejson/decoder.py", line 416, in raw_decode return self.scan_once(s, idx=_w(s, idx).end()) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ simplejson.errors.JSONDecodeError: Expecting value: line 1 column 1 (char 0) During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/config/custom_components/kia_uvo/coordinator.py", line 126, in _async_update_data await self.hass.async_add_executor_job( File "/usr/local/lib/python3.12/concurrent/futures/thread.py", line 58, in run result = self.fn(*self.args, **self.kwargs) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/VehicleManager.py", line 113, in check_and_force_update_vehicles self.update_vehicle_with_cached_state(vehicle_id) File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/VehicleManager.py", line 92, in update_vehicle_with_cached_state self.api.update_geocoded_location( File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/ApiImpl.py", line 118, in update_geocoded_location response = response.json() ^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/requests/models.py", line 978, in json raise RequestsJSONDecodeError(e.msg, e.doc, e.pos) requests.exceptions.JSONDecodeError: Expecting value: line 1 column 1 (char 0) During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/config/custom_components/kia_uvo/coordinator.py", line 135, in _async_update_data await self.hass.async_add_executor_job( File "/usr/local/lib/python3.12/concurrent/futures/thread.py", line 58, in run result = self.fn(*self.args, **self.kwargs) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/VehicleManager.py", line 85, in update_all_vehicles_with_cached_state self.update_vehicle_with_cached_state(vehicle_id) File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/VehicleManager.py", line 92, in update_vehicle_with_cached_state self.api.update_geocoded_location( File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/ApiImpl.py", line 118, in update_geocoded_location response = response.json() ^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/requests/models.py", line 978, in json raise RequestsJSONDecodeError(e.msg, e.doc, e.pos) requests.exceptions.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

dagobert commented 1 month ago

It seems to me that the returned content is empty.

Is there any way to help you debug this.

The problem might be that the server is checking the user agent. this is the case with other integrations that access API of service providers that do not like random scripts to access their service.

johny-mnemonic commented 1 month ago

@cdnninja thanks!

It looks to me like it is exclusively failing in the update_geocoded_location call. At least I don't see other calls failing now.

2024-08-15 18:50:40.546 DEBUG (SyncWorker_12) [hyundai_kia_connect_api.ApiImpl] hyundai_kia_connect_api - Running update geocode location with value: https://nominatim.openstreetmap.org/reverse?lat=4X.X29656&lon=1X.X009092&format=json&addressdetails=1&zoom=18
2024-08-15 18:50:40.613 ERROR (MainThread) [custom_components.kia_uvo.coordinator] Force update failed, falling back to cached: Traceback (most recent call last):
File "/usr/local/lib/python3.12/site-packages/requests/models.py", line 974, in json
return complexjson.loads(self.text, **kwargs)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/simplejson/__init__.py", line 514, in loads
return _default_decoder.decode(s)
^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/simplejson/decoder.py", line 386, in decode
obj, end = self.raw_decode(s)
^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/simplejson/decoder.py", line 416, in raw_decode
return self.scan_once(s, idx=_w(s, idx).end())
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
simplejson.errors.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/config/custom_components/kia_uvo/coordinator.py", line 126, in _async_update_data
await self.hass.async_add_executor_job(
File "/usr/local/lib/python3.12/concurrent/futures/thread.py", line 58, in run
result = self.fn(*self.args, **self.kwargs)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/VehicleManager.py", line 115, in check_and_force_update_vehicles
self.update_vehicle_with_cached_state(vehicle_id)
File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/VehicleManager.py", line 92, in update_vehicle_with_cached_state
self.api.update_geocoded_location(
File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/ApiImpl.py", line 118, in update_geocoded_location
response = response.json()
^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/requests/models.py", line 978, in json
raise RequestsJSONDecodeError(e.msg, e.doc, e.pos)
requests.exceptions.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
2024-08-15 18:50:40.881 DEBUG (SyncWorker_3) [hyundai_kia_connect_api.KiaUvoApiEU] hyundai_kia_connect_api - get_cached_vehicle_status response: {'retCode': 'S', 'resCode': '0000', 'resMsg': {'vehicleStatusInfo': {'vehicleLocation': {'coord': {'lat': 4X.X29656, 'lon': 1X.X09092, 'alt': 0, 'type': 0}, 'head': 186, 'speed': {'value': 0, 'unit': 0}, 'accuracy': {'hdop': 0, 'pdop': 1}, 'time': '20240815154804'}, 'vehicleStatus': {'airCtrlOn': False, 'engine': False, 'doorLock': True, 'doorOpen': {'frontLeft': 0, 'frontRight': 0, 'backLeft': 0, 'backRight': 0}, 'trunkOpen': False, 'airTemp': {'value': '02H', 'unit': 0, 'hvacTempType': 1}, 'defrost': False, 'acc': False, 'evStatus': {'batteryCharge': False, 'batteryStatus': 68, 'batteryPlugin': 0, 'remainTime2': {'etc1': {'value': 13, 'unit': 1}, 'etc2': {'value': 255, 'unit': 1}, 'etc3': {'value': 60, 'unit': 1}, 'atc': {'value': 60, 'unit': 1}}, 'drvDistance': [{'rangeByFuel': {'evModeRange': {'value': 284, 'unit': 1}, 'totalAvailableRange': {'value': 284, 'unit': 1}}, 'type': 2}], 'reservChargeInfos': {'reservChargeInfo': {'reservChargeInfoDetail': {'reservInfo': {'day': [2, 3], 'time': {'time': '0750', 'timeSection': 0}}, 'reservChargeSet': False, 'reservFatcSet': {'defrost': False, 'airTemp': {'value': '15H', 'unit': 0, 'hvacTempType': 1}, 'airCtrl': 0, 'heating1': 0}}}, 'offpeakPowerInfo': {'offPeakPowerTime1': {'starttime': {'time': '1200', 'timeSection': 0}, 'endtime': {'time': '1200', 'timeSection': 0}}, 'offPeakPowerFlag': 1}, 'reserveChargeInfo2': {'reservChargeInfoDetail': {'reservInfo': {'day': [1, 4, 5], 'time': {'time': '1140', 'timeSection': 1}}, 'reservChargeSet': False, 'reservFatcSet': {'defrost': False, 'airTemp': {'value': '15H', 'unit': 0, 'hvacTempType': 1}, 'airCtrl': 0, 'heating1': 0}}}, 'reservFlag': 0, 'ect': {'start': {'day': 0, 'time': {'time': '0000', 'timeSection': 0}}, 'end': {'day': 0, 'time': {'time': '0000', 'timeSection': 0}}}, 'targetSOClist': [{'targetSOClevel': 80, 'plugType': 0}, {'targetSOClevel': 80, 'plugType': 1}]}}, 'ign3': False, 'hoodOpen': False, 'transCond': True, 'steerWheelHeat': 0, 'sideBackWindowHeat': 0, 'tirePressureLamp': {'tirePressureLampAll': 0, 'tirePressureLampFL': 0, 'tirePressureLampFR': 0, 'tirePressureLampRL': 0, 'tirePressureLampRR': 0}, 'battery': {'batSoc': 78, 'batState': 0}, 'sleepModeCheck': True, 'time': '20240815154805', 'remoteWaitingTimeAlert': {'remoteControlAvailable': 1, 'remoteControlWaitingTime': 168, 'elapsedTime': '00:07:22'}, 'systemCutOffAlert': 0, 'tailLampStatus': 0, 'hazardStatus': 0}, 'odometer': {'value': 43565.4, 'unit': 1}}}, 'msgId': '813b0b70-5b26-11ef-9799-839f8b19878c'}

If I am reading the log correctly the get_cached_vehicle_status response: is showing the json that it is trying to parse, which looks valid at first glance and also contains the location (I have masked the exact coordinates).

Edit: Wait a minute! It seems like @dagobert is actually right. In the successful fetch it looks like this:

2024-08-15 18:52:52.574 DEBUG (SyncWorker_0) [hyundai_kia_connect_api.ApiImpl] hyundai_kia_connect_api - Running update geocode location with value: https://nominatim.openstreetmap.org/reverse?lat=4X.X29656&lon=1X.X09092&format=json&addressdetails=1&zoom=18
2024-08-15 18:52:52.935 DEBUG (SyncWorker_0) [hyundai_kia_connect_api.ApiImpl] hyundai_kia_connect_api - geocode location response: {'place_id': 113238186, 'licence': 'Data © OpenStreetMap contributors, ODbL 1.0. http://osm.org/copyright', 'osm_type': 'node', 'osm_id': 4328386754, 'lat': '4X.X295133', 'lon': '1X.X089138', 'class': 'place', 'type': 'house', 'place_rank': 30, 'importance': 9.99999999995449e-06, 'addresstype': 'place', 'name': '', 'display_name': 'NNN, XXXXXXXXX, XXXXXX, XXXXXX, XXXXXXX, okres Beroun, Střední Čechy, NNNNN, Česko', 'address': {'house_number': 'NNN', 'road': 'XXXXXX', 'village': 'XXXXXXXX', 'town': 'XXXXXXXXX', 'municipality': 'okres Beroun', 'ISO3166-2-lvl7': 'CZ-202', 'state': 'Střední Čechy', 'postcode': 'NNNNN', 'country': 'Česko', 'country_code': 'cz'}, 'boundingbox': ['4X.X294633', '4X.X295633', '1X.X0088638', '1X.X0089638']}
2024-08-15 18:52:52.936 DEBUG (MainThread) [custom_components.kia_uvo.coordinator] Finished fetching kia_uvo data in 3.098 seconds (success: True)

For some reason the geocode location response: is missing from the failed attempts. Is this because the printing of debug info is in the same block as the json parsing and behind it, so if the json parsing fails the printing of debug info doesn't happen at all?

Could it be, that only people who enabled the Enable Geolocation Entity using OpenStreetMap in the config are having this issue? 🧐 I am disabling it to test it now.

cdnninja commented 1 month ago

Yes a known bug exists around location. I suspect from time to time the geocode api goes down.

When I'm home I'll move the debug line up to see the unparsed response in the logs. We can also adjust that to fail gracefully.

cdnninja commented 1 month ago

I added more debug and try catch. Could you retry on latest.

https://github.com/Hyundai-Kia-Connect/hyundai_kia_connect_api/pull/611

Taomyn commented 1 month ago

Had to revert back to the previous version as this one lost me the two update entities: kia_uvo.force_update and kia_uvo.update

johny-mnemonic commented 1 month ago

@cdnninja seems like the new package is not available in pypi. The new version fails to install with this error:

Setup failed for custom integration 'kia_uvo': Requirements for kia_uvo not found: ['hyundai_kia_connect_api==3.22.4']
dagobert commented 1 month ago

Before updateing to the new master, having the same error as @johny-mnemonic I did a reload in the integration-device page. this reload resulted in correct values. Hence, it seem that the integration is not really broken, but there is probably an issue with the communication, such as blocking by the server of some kind.

cdnninja commented 1 month ago

Please try latest should be good now.

johny-mnemonic commented 1 month ago

@cdnninja yep, installation passes now and debug output also looks good. Thanks! Unfortunately I am leaving for a vacation tomorrow, so won't be able to test it thoroughly for a while...

johny-mnemonic commented 1 month ago

OK, it failed fast :wink:

2024-08-16 23:01:57.042 DEBUG (SyncWorker_14) [hyundai_kia_connect_api.ApiImpl] hyundai_kia_connect_api - Running update geocode location with value: https://nominatim.openstreetmap.org/reverse?lat=48.737783&lon=14.109275&format=json&addressdetails=1&zoom=18
2024-08-16 23:01:57.111 DEBUG (SyncWorker_14) [hyundai_kia_connect_api.ApiImpl] hyundai_kia_connect_api - geocode location raw response: <Response [403]>
2024-08-16 23:01:57.113 ERROR (MainThread) [custom_components.kia_uvo.coordinator] Unexpected error fetching kia_uvo data
Traceback (most recent call last):
File "/usr/local/lib/python3.12/site-packages/requests/models.py", line 974, in json
return complexjson.loads(self.text, **kwargs)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/simplejson/__init__.py", line 514, in loads
return _default_decoder.decode(s)
^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/simplejson/decoder.py", line 386, in decode
obj, end = self.raw_decode(s)
^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/simplejson/decoder.py", line 416, in raw_decode
return self.scan_once(s, idx=_w(s, idx).end())
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
simplejson.errors.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/ApiImpl.py", line 121, in update_geocoded_location
response = response.json()
^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/requests/models.py", line 978, in json
raise RequestsJSONDecodeError(e.msg, e.doc, e.pos)
requests.exceptions.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 354, in _async_refresh
self.data = await self._async_update_data()
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/config/custom_components/kia_uvo/coordinator.py", line 145, in _async_update_data
await self.hass.async_add_executor_job(
File "/usr/local/lib/python3.12/concurrent/futures/thread.py", line 58, in run
result = self.fn(*self.args, **self.kwargs)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/VehicleManager.py", line 85, in update_all_vehicles_with_cached_state
self.update_vehicle_with_cached_state(vehicle_id)
File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/VehicleManager.py", line 92, in update_vehicle_with_cached_state
self.api.update_geocoded_location(
File "/usr/local/lib/python3.12/site-packages/hyundai_kia_connect_api/ApiImpl.py", line 122, in update_geocoded_location
except requests.RequestsJSONDecodeError:
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
AttributeError: module 'requests' has no attribute 'RequestsJSONDecodeError'
2024-08-16 23:01:57.117 DEBUG (MainThread) [custom_components.kia_uvo.coordinator] Finished fetching kia_uvo data in 2.720 seconds (success: False)

The change of debug logging introduced an error, but good news is, that it still gave us what we wanted. It looks like the request for the geolocation is ending with error 403 (unauthorized). No clue why, but I wouldn't be surprised if it was a bad way to handle rate limiting.

@cdnninja what about catching this 403 response and silently ignoring it (maybe better print warning that geolocation might not be up-to-date)? Or just generally finish successfully no matter on which error the request for geolocation fails :thinking:

cdnninja commented 1 month ago

I am not seeing the 403 in the logs. Was a part of the logs missing? I will work on fixing that exception RequestsJSONDecodeError catch as well.

cdnninja commented 1 month ago

Latest version will hopefully catch that error and continue. Thanks for testing. Since I personally don't use this integration anymore it is hard for me to test.

johny-mnemonic commented 1 month ago

Sorry, github markup ignored the formatting when hidden in detail block, so it was really hard to spot it in the log (fixed). It is right on the second line:

2024-08-16 23:01:57.111 DEBUG (SyncWorker_14) [hyundai_kia_connect_api.ApiImpl] hyundai_kia_connect_api - geocode location raw response: <Response [403]>
cdnninja commented 1 month ago

Okay thanks. The try catch I put in should handle that or any other failure if working right.