Closed jprouty closed 1 year ago
I have made the mentioned edit above in module bimmer_connected.account#get_vehicles and I will report back findings.
Sorry for the slow response. I've also set the logging for bimmer_connected to debug level. Here is an example of the latest error, with included logging of the status code + full response text inserted just prior to the throwing .json()
call;
2022-09-27 22:31:26.001 DEBUG (MainThread) [bimmer_connected.account] Getting vehicle list
2022-09-27 22:31:26.396 DEBUG (MainThread) [bimmer_connected.api.authentication] Received unauthorized response, refreshing token.
2022-09-27 22:31:26.431 DEBUG (MainThread) [bimmer_connected.api.authentication] Authenticating with refresh token for North America & Rest of World.
2022-09-27 22:31:27.331 DEBUG (MainThread) [bimmer_connected.account] get_vehicles: 401 << (jprouty added this, content immediately follows, which is of length zero - matches the error message from the stack trace).
2022-09-27 22:31:27.336 ERROR (MainThread) [homeassistant.components.bmw_connected_drive.coordinator] Unexpected error fetching bmw_connected_drive-<REDACTED_EMAIL> data: Expecting value: line 1 column 1 (char 0)
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 205, in _async_refresh
self.data = await self._async_update_data()
File "/usr/src/homeassistant/homeassistant/components/bmw_connected_drive/coordinator.py", line 57, in _async_update_data
await self.account.get_vehicles()
File "/usr/local/lib/python3.10/site-packages/bimmer_connected/account.py", line 102, in get_vehicles
vehicle_state = state_response.json()
File "/usr/local/lib/python3.10/site-packages/httpx/_models.py", line 743, in json
return jsonlib.loads(self.text, **kwargs)
File "/usr/local/lib/python3.10/json/__init__.py", line 346, in loads
return _default_decoder.decode(s)
File "/usr/local/lib/python3.10/json/decoder.py", line 337, in decode
obj, end = self.raw_decode(s, idx=_w(s, 0).end())
File "/usr/local/lib/python3.10/json/decoder.py", line 355, in raw_decode
raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
...
2022-09-28 00:31:49.002 DEBUG (MainThread) [bimmer_connected.account] Getting vehicle list
2022-09-28 00:31:49.365 DEBUG (MainThread) [bimmer_connected.api.authentication] Received unauthorized response, refreshing token.
2022-09-28 00:31:49.400 DEBUG (MainThread) [bimmer_connected.api.authentication] Authenticating with refresh token for North America & Rest of World.
2022-09-28 00:31:50.212 DEBUG (MainThread) [bimmer_connected.account] get_vehicles: 401
2022-09-28 00:31:50.215 ERROR (MainThread) [homeassistant.components.bmw_connected_drive.coordinator] Unexpected error fetching bmw_connected_drive-<REDACTED_EMAIL> data: Expecting value: line 1 column 1 (char 0)
...
2022-09-28 16:35:48.002 DEBUG (MainThread) [bimmer_connected.account] Getting vehicle list
2022-09-28 16:35:48.390 DEBUG (MainThread) [bimmer_connected.api.authentication] Received unauthorized response, refreshing token.
2022-09-28 16:35:48.424 DEBUG (MainThread) [bimmer_connected.api.authentication] Authenticating with refresh token for North America & Rest of World.
2022-09-28 16:35:49.053 DEBUG (MainThread) [bimmer_connected.account] get_vehicles: 401
2022-09-28 16:35:49.056 ERROR (MainThread) [homeassistant.components.bmw_connected_drive.coordinator] Unexpected error fetching bmw_connected_drive-<REDACTED_EMAIL> data: Expecting value: line 1 column 1 (char 0)
...
2022-09-28 17:36:00.003 DEBUG (MainThread) [bimmer_connected.account] Getting vehicle list
2022-09-28 17:36:00.538 DEBUG (MainThread) [bimmer_connected.api.authentication] Received unauthorized response, refreshing token.
2022-09-28 17:36:00.570 DEBUG (MainThread) [bimmer_connected.api.authentication] Authenticating with refresh token for North America & Rest of World.
2022-09-28 17:36:01.362 DEBUG (MainThread) [bimmer_connected.account] get_vehicles: 401
2022-09-28 17:36:01.366 ERROR (MainThread) [homeassistant.components.bmw_connected_drive.coordinator] Unexpected error fetching bmw_connected_drive-<REDACTED_EMAIL> data: Expecting value: line 1 column 1 (char 0)
...
2022-09-28 20:36:37.001 DEBUG (MainThread) [bimmer_connected.account] Getting vehicle list
2022-09-28 20:36:37.365 DEBUG (MainThread) [bimmer_connected.api.authentication] Received unauthorized response, refreshing token.
2022-09-28 20:36:37.400 DEBUG (MainThread) [bimmer_connected.api.authentication] Authenticating with refresh token for North America & Rest of World.
2022-09-28 20:36:38.115 DEBUG (MainThread) [bimmer_connected.account] get_vehicles: 401
2022-09-28 20:36:38.119 ERROR (MainThread) [homeassistant.components.bmw_connected_drive.coordinator] Unexpected error fetching bmw_connected_drive-<REDACTED_EMAIL> data: Expecting value: line 1 column 1 (char 0)
It appears that an initial request fails due to a 401, the library detects this, and attempts to refresh it's OAuth token. It then fails again on the follow up request to get_vehicles (possibly due to a race condition in setting the token? Or a missing await?). All subsequent requests to get_vehicles work, until the token expires. The odd part is that the frequency of the OAuth token expiring is rather irregular (22h, 16h, 1h, 3h), but always occur right on the hour (offset in these logs to around minute 35/36).
This is very interesting - like you said, it seems as if the Bearer token is not updated for the following request.
We will need to debug this further - I am using the same login flow (rest_of_world instead north_america, but the code is the same) and haven't seen this issue.
Please adjust bimmer_connected/api/authentication.py#L83-89
:
if response.status_code == 401:
async with self.login_lock:
_LOGGER.debug("Received unauthorized response, refreshing token.")
_LOGGER.debug("Old token: %s", self.access_token)
await self.login()
request.headers["authorization"] = f"Bearer {self.access_token}"
request.headers["bmw-session-id"] = self.session_id
_LOGGER.debug("New token: %s, Token in header: %s", self.access_token, request.headers["authorization"])
yield request
Maybe we get more insights this way.
Roger; I have made the suggested edits. Thanks for the code pointer
Looks as expected/desired:
2022-10-01 17:22:06.001 DEBUG (MainThread) [bimmer_connected.account] Getting vehicle list
2022-10-01 17:22:06.420 DEBUG (MainThread) [bimmer_connected.api.authentication] Received unauthorized response, refreshing token
.
2022-10-01 17:22:06.420 DEBUG (MainThread) [bimmer_connected.api.authentication] Old token: 8ROKJ9R1HE_HnYque2PxRwR4Fvs
2022-10-01 17:22:06.453 DEBUG (MainThread) [bimmer_connected.api.authentication] Authenticating with refresh token for North Amer
ica & Rest of World.
2022-10-01 17:22:06.947 DEBUG (MainThread) [bimmer_connected.api.authentication] Refreshed token: DAUmR-idxMtKIBNzp8KKjjq59WV 202
2-10-02 01:21:05.734838 h0SdcF3-HIO6P4cQAknPIJtZO_s
2022-10-01 17:22:06.947 DEBUG (MainThread) [bimmer_connected.api.authentication] New token: DAUmR-idxMtKIBNzp8KKjjq59WV, Token in
header: Bearer DAUmR-idxMtKIBNzp8KKjjq59WV
2022-10-01 17:22:07.058 DEBUG (MainThread) [bimmer_connected.account] get_vehicles: 401
2022-10-01 17:22:07.064 ERROR (MainThread) [homeassistant.components.bmw_connected_drive.coordinator] Unexpected error fetching b
mw_connected_drive-jeff.prouty@gmail.com data: Expecting value: line 1 column 1 (char 0)
It seems like BMW's connected drive API has a bug (some sort of caching causing the new token not to be accepted right away). (Or, there's something funky going on with the httpx code - however, your code looks very near the httpx example, which does an OAuth token refresh).
Just for fun, I am going to interject a 10 second sleep immediately before the 2nd yield / attempt after the bearer token has been refreshed.
Yeah, I've double checked the httpx
example as well but the code should be fine. We should also be on the same httpx
version, as that is pinned by HA's package_constraints.txt.
So it could actually be an timing issue on BMW side, although it is weird that you seem to be the only one who is having it (still believing you, the logs don't lie ;) ).
This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.
Noticed this is closed but I do get this same issue, sometimes 5 times a day, sometimes 0, you're not alone haha
Expecting value: line 1 column 1 (char 0)1718
Traceback (most recent call last):
File "C:\Users\Administrator\Desktop\bmw\main.py", line 44, in update_vehicles
await get_vehicles()
File "C:\Users\Administrator\Desktop\bmw\main.py", line 35, in get_vehicles
await account.get_vehicles()
File "C:\Users\Administrator\AppData\Local\Programs\Python\Python311\Lib\site-packages\bimmer_connected\account.py", line 109, in get_vehicles
vehicle_state = state_response.json()
^^^^^^^^^^^^^^^^^^^^^
File "C:\Users\Administrator\AppData\Local\Programs\Python\Python311\Lib\site-packages\httpx_models.py", line 756, in json
return jsonlib.loads(self.text, **kwargs)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "C:\Users\Administrator\AppData\Local\Programs\Python\Python311\Lib\json__init__.py", line 346, in loads
return _default_decoder.decode(s)
^^^^^^^^^^^^^^^^^^^^^^^^^^
File "C:\Users\Administrator\AppData\Local\Programs\Python\Python311\Lib\json\decoder.py", line 337, in decode
obj, end = self.raw_decode(s, idx=_w(s, 0).end())
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "C:\Users\Administrator\AppData\Local\Programs\Python\Python311\Lib\json\decoder.py", line 355, in raw_decode
raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
Describe the issue
I am receiving the error below spuriously in my
home-assistant.log
(about 3 / day). The car is a 2019 G05, running 07/2021.85. I rarely use the BMW connected app, and there are no other integrations setup against this BMW account. HA is on a RPi 4, running the latest version:Please let me know if there's additional logging / information I can provide to assist. (The next step seems like adding a debug log of the full text response for the failing request).
Expected behavior
API responses to be parsed correctly and without error.
Which Home Assistant version are you using?
2022.9.5
What was the last working version of Home Assistant Core?
No response
What is your region?
North America
MyBMW website
Number of cars
Output of bimmer_connected fingerprint
No response
Anything in the logs that might be useful for us?
No response
Additional information
No response