bimmer_connected icon indicating copy to clipboard operation
bimmer_connected copied to clipboard

Published 20 hours ago • verified publisher icon bimmerconnected

Invalid json response from request in account.py#get_vehicles

Open jprouty opened this issue 1 year ago • 7 comments

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:

Home Assistant 2022.9.5
Supervisor 2022.09.1
Operating System 9.0
Frontend 20220907.2 - latest

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).

2022-09-18 13:35:16.925 ERROR (MainThread) [homeassistant.components.bmw_connected_drive.coordinator] Unexpected error fetching bmw_connected_drive-EMAIL_REDACTED data: Expecting value: line 1 column 1 (char 0)
  File "/usr/src/homeassistant/homeassistant/components/bmw_connected_drive/coordinator.py", line 57, in _async_update_data
< STACK TRACE IDENTICAL AS BELOW >
2022-09-18 15:36:05.039 ERROR (MainThread) [homeassistant.components.bmw_connected_drive.coordinator] Unexpected error fetching bmw_connected_drive-EMAIL_REDACTED data: Expecting value: line 1 column 1 (char 0)
  File "/usr/src/homeassistant/homeassistant/components/bmw_connected_drive/coordinator.py", line 57, in _async_update_data
< STACK TRACE IDENTICAL AS BELOW >
2022-09-18 20:38:05.982 ERROR (MainThread) [homeassistant.components.bmw_connected_drive.coordinator] Unexpected error fetching bmw_connected_drive-EMAIL_REDACTED data: Expecting value: line 1 column 1 (char 0)
  File "/usr/src/homeassistant/homeassistant/components/bmw_connected_drive/coordinator.py", line 57, in _async_update_data
< STACK TRACE IDENTICAL AS BELOW >
2022-09-19 01:23:23.265 ERROR (MainThread) [homeassistant.components.bmw_connected_drive.coordinator] Unexpected error fetching bmw_connected_drive-EMAIL_REDACTED 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_refres
h
    self.data = await self._async_update_data()
  File "/usr/src/homeassistant/homeassistant/components/bmw_connected_drive/coordinator.py", line 57, i
n _async_update_data
    await self.account.get_vehicles()
  File "/usr/local/lib/python3.10/site-packages/bimmer_connected/account.py", line 79, in get_vehicles
    for vehicle_base in 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)

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

  • [X] I can still successfully login to the BMW MyBMW website and the car status is available there.
  • [X] I have MyBMW enabled for my vehicle.

Number of cars

  • [ ] I have 2 or more cars linked to the MyBMW account.
  • [ ] I have a Mini vehicle linked to my account.

Output of bimmer_connected fingerprint

No response

Anything in the logs that might be useful for us?

No response

Additional information

No response

jprouty avatar Sep 19 '22 22:09 jprouty

I have made the mentioned edit above in module bimmer_connected.account#get_vehicles and I will report back findings.

jprouty avatar Sep 19 '22 23:09 jprouty

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).

jprouty avatar Sep 29 '22 17:09 jprouty

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.

rikroe avatar Oct 01 '22 13:10 rikroe

Roger; I have made the suggested edits. Thanks for the code pointer

jprouty avatar Oct 01 '22 15:10 jprouty

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
[email protected] 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).

jprouty avatar Oct 02 '22 15:10 jprouty

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.

jprouty avatar Oct 02 '22 15:10 jprouty

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 ;) ).

rikroe avatar Oct 02 '22 21:10 rikroe