Implement Fleet API vehicle_data rate limiting

[RichieB2B]

I just read the Tesla Fleet API membership tiers which mention:

So we should limit the vehicle_data request calls to 1 per 5 minutes. The start/stop commands and wake limits should be OK as is.

[blach]

I've installed the latest version of TWCManager and I'm now using it with tesla-http-proxy running on another server on the local network and the Fleet API successfully.

It works for a while, however I quickly run into the rate limits because TWCManager tries to start and stop charging the vehicle way too frequently. This results in the Tesla server returning HTTP status 429.

I'm not sure if the charge start and stop commands count towards the 50 API request per car per day ("Commands limits") or the 5 API requests per car per day ("Charging commands").

Also, TWCManager tries to send a command to start charging even when the vehicle is already fully charged.

[MikeBishop]

Ultimately, I'd love to take the suggestion in #562 that we use the Pi's BT interface to directly command the car without going through the API. My initial experiments with that using the Tesla command line tools haven't been successful, though. But that would let us completely bypass these limits.

[blach]

Yes, I also think that this would be the way to go.

Do you currently have the Fleet API working with TWCManager and are not running into the rate limits due to too many charge start/stop commands?

Is there something I can do with the existing configuration options to limit the number of commands that are sent to the Fleet API?

[RichieB2B]

@blach Start charging attempts should be very limited because of the vehicle.stopAskingToStartCharging == True mechanism in TWCManager. How frequent do you see "Car API cmd charge_start" in your log file?

All I see is TeslaAPI calls to /api/1/vehicles/<VIN> every minute to check if the car is_awake(). If it is awake those calls become /api/1/vehicles/<VIN>/vehicle_data which should count toward the "Device data limits" (200 / requests / vehicle / day). Personally I have not seen any HTTP 429 responses though.

[blach]

This morning I was running a mix of an old version of TWCManager with the latest TeslaAPI.py. I did this because I made modifications to the source code in the past to work with my Fronius inverter setup.

The log file below is from that Frankenstein-version of TWCManager, so it might not reflect the behavior of the main branch.

I have since then updated all files to the main branch.

Currently there is not enough solar power, so I'll check again tomorrow and let you know.

Anyway, this morning, it tried to start charging both cars about every minute, even though the server already returned "complete" or "is_charging".

I'm not sure if this will be fixed by updating the rest of the source files of TWCManager to the versions from the main branch.

Anyway, here is part of the log file from this morning:

Jun 10 06:39:43 TWCManager python3[19906]: 06:39:43 🚗 TeslaAPI 13 Car API cmd charge_start <Response [200]>
Jun 10 06:39:43 TWCManager python3[19906]: 06:39:43 🚗 TeslaAPI 17 NCC-1701-D: start charge response{'response': {'result': False, 'string': 'car could not execute command: complete'}, 'error': '', 'error_description': ''}
Jun 10 06:39:43 TWCManager python3[19906]: 06:39:43 🚗 TeslaAPI 20 NCC-1701-D is done charging or already trying to charge or not connected to a charger.  Stop asking to start charging.
Jun 10 06:39:48 TWCManager python3[19906]: 06:39:48 🚗 TeslaAPI 13 Car API cmd charge_start <Response [200]>
Jun 10 06:39:48 TWCManager python3[19906]: 06:39:48 🚗 TeslaAPI 17 NCC-74656: start charge response{'response': {'result': True, 'reason': ''}}
Jun 10 06:40:50 TWCManager python3[19906]: 06:40:50 🚗 TeslaAPI 13 Car API cmd charge_start <Response [200]>
Jun 10 06:40:50 TWCManager python3[19906]: 06:40:50 🚗 TeslaAPI 17 NCC-1701-D: start charge response{'response': {'result': False, 'string': 'car could not execute command: complete'}, 'error': '', 'error_description': ''}
Jun 10 06:40:50 TWCManager python3[19906]: 06:40:50 🚗 TeslaAPI 20 NCC-1701-D is done charging or already trying to charge or not connected to a charger.  Stop asking to start charging.
Jun 10 06:40:55 TWCManager python3[19906]: 06:40:55 🚗 TeslaAPI 13 Car API cmd charge_start <Response [200]>
Jun 10 06:40:55 TWCManager python3[19906]: 06:40:55 🚗 TeslaAPI 17 NCC-74656: start charge response{'response': {'result': False, 'string': 'car could not execute command: is_charging'}, 'error': '', 'error_description': ''}
Jun 10 06:40:55 TWCManager python3[19906]: 06:40:55 🚗 TeslaAPI 20 NCC-74656 is done charging or already trying to charge or not connected to a charger.  Stop asking to start charging.
Jun 10 06:41:56 TWCManager python3[19906]: 06:41:56 🚗 TeslaAPI 13 Car API cmd charge_start <Response [200]>
Jun 10 06:41:56 TWCManager python3[19906]: 06:41:56 🚗 TeslaAPI 17 NCC-1701-D: start charge response{'response': {'result': False, 'string': 'car could not execute command: complete'}, 'error': '', 'error_description': ''}
Jun 10 06:41:56 TWCManager python3[19906]: 06:41:56 🚗 TeslaAPI 20 NCC-1701-D is done charging or already trying to charge or not connected to a charger.  Stop asking to start charging.
Jun 10 06:42:02 TWCManager python3[19906]: 06:42:02 🚗 TeslaAPI 13 Car API cmd charge_start <Response [200]>
Jun 10 06:42:02 TWCManager python3[19906]: 06:42:02 🚗 TeslaAPI 17 NCC-74656: start charge response{'response': {'result': False, 'string': 'car could not execute command: is_charging'}, 'error': '', 'error_description': ''}
Jun 10 06:42:02 TWCManager python3[19906]: 06:42:02 🚗 TeslaAPI 20 NCC-74656 is done charging or already trying to charge or not connected to a charger.  Stop asking to start charging.
Jun 10 06:43:04 TWCManager python3[19906]: 06:43:04 🚗 TeslaAPI 13 Car API cmd charge_start <Response [200]>
Jun 10 06:43:04 TWCManager python3[19906]: 06:43:04 🚗 TeslaAPI 17 NCC-1701-D: start charge response{'response': {'result': False, 'string': 'car could not execute command: complete'}, 'error': '', 'error_description': ''}
Jun 10 06:43:04 TWCManager python3[19906]: 06:43:04 🚗 TeslaAPI 20 NCC-1701-D is done charging or already trying to charge or not connected to a charger.  Stop asking to start charging.
Jun 10 06:43:09 TWCManager python3[19906]: 06:43:09 🚗 TeslaAPI 13 Car API cmd charge_start <Response [200]>
Jun 10 06:43:09 TWCManager python3[19906]: 06:43:09 🚗 TeslaAPI 17 NCC-74656: start charge response{'response': {'result': False, 'string': 'car could not execute command: is_charging'}, 'error': '', 'error_description': ''}
Jun 10 06:43:09 TWCManager python3[19906]: 06:43:09 🚗 TeslaAPI 20 NCC-74656 is done charging or already trying to charge or not connected to a charger.  Stop asking to start charging.
Jun 10 06:44:11 TWCManager python3[19906]: 06:44:11 🚗 TeslaAPI 13 Car API cmd charge_start <Response [200]>
Jun 10 06:44:11 TWCManager python3[19906]: 06:44:11 🚗 TeslaAPI 17 NCC-1701-D: start charge response{'response': {'result': False, 'string': 'car could not execute command: complete'}, 'error': '', 'error_description': ''}
Jun 10 06:44:11 TWCManager python3[19906]: 06:44:11 🚗 TeslaAPI 20 NCC-1701-D is done charging or already trying to charge or not connected to a charger.  Stop asking to start charging.
Jun 10 06:44:16 TWCManager python3[19906]: 06:44:16 🚗 TeslaAPI 13 Car API cmd charge_start <Response [200]>
Jun 10 06:44:16 TWCManager python3[19906]: 06:44:16 🚗 TeslaAPI 17 NCC-74656: start charge response{'response': {'result': False, 'string': 'car could not execute command: is_charging'}, 'error': '', 'error_description': ''}
Jun 10 06:44:16 TWCManager python3[19906]: 06:44:16 🚗 TeslaAPI 20 NCC-74656 is done charging or already trying to charge or not connected to a charger.  Stop asking to start charging.

[RichieB2B]

So TeslaAPI is saying:

Jun 10 06:39:43 TWCManager python3[19906]: 06:39:43 🚗 TeslaAPI 20 NCC-1701-D is done charging or already trying to charge or not connected to a charger.  Stop asking to start charging.

but it does not stop asking to start charging:

Jun 10 06:40:50 TWCManager python3[19906]: 06:40:50 🚗 TeslaAPI 17 NCC-1701-D: start charge response{'response': {'result': False, 'string': 'car could not execute command: complete'}, 'error': '', 'error_description': ''}

There are 5 situations where stopAskingToStartCharging is reset:

1. when the car starts charging
2. when TWCManager decides it needs to stop charging cars
3. on a policy change like switching from "Track Green Energy" to "Charge Now"
4. when a car leaves home (location change)
5. when a car arrives home (location change)

Assuming non of these applied every minute in the above log the question is: why does TWCManager not respect stopAskingToStartCharging == True ?

[blach]

I'll check how it behaves tomorrow when there is enough solar power.

Maybe the issue was due to a mix of the old and new source code.

[blach]

stopAskingToStartCharging is also set to False here:

TWCManager/lib/TWCManager/TWCSlave.py

Line 559 in b4d1536

vehicle.stopAskingToStartCharging = False

It looks like stopAskingToStartCharging is reset for all cars if at least one TWCSlave has reportedAmpsActual > 1.0.

I do have two TWCs ("slaves") and two cars and one of them was charging. So I think that line was executed in my case.

[blach]

Ok, I just tested this:

• I have two cars connected to two TWCs
• One of the two cars has finished charging, the other has not yet reached the desired SOC
• I started TWCManager
• Since enough solar power is available, it sent commands to start charging to both vehicles
• One started charging, the other reports "complete":

TeslaAPI 17 NCC-1701-D: start charge response{'response': {'result': True, 'reason': ''}}
TeslaAPI 17 NCC-74656: start charge response{'response': {'result': False, 'string': 'car could not execute command: complete'}, 'error': '', 'error_description': ''}

I added log statements to TWCSlave.py to see if that code is executed.

And indeed, this code in send_slave_heartbeat is called about every second:

TWCManager/lib/TWCManager/TWCSlave.py

Lines 546 to 559 in b4d1536

	elif self.reportedAmpsActual >= 1.0:
	# At least one plugged in car is successfully charging. We don't
	# know which car it is, so we must set
	# vehicle.stopAskingToStartCharging = False on all vehicles such
	# that if any vehicle is not charging without us calling
	# car_api_charge(False), we'll try to start it charging again at
	# least once. This probably isn't necessary but might prevent
	# some unexpected case from never starting a charge. It also
	# seems less confusing to see in the output that we always try
	# to start API charging after the car stops taking a charge.
	for vehicle in self.master.getModuleByName(
	"TeslaAPI"
	).getCarApiVehicles():
	vehicle.stopAskingToStartCharging = False

The "slave" that is charging causes stopAskingToStartCharging to be set to False for all vehicles.

This results in "Car API cmd charge_start" being sent every minute, running into the rate limits.

I'm going to comment out those lines in TWCSlave.py now.

I'm wondering why you aren't running into this same issue?

[blach]

With those lines in TWCSlave.py commented out, I now get this in the log file:

Jun 11 13:21:43 TWCManager python3[28742]: 13:21:43 🚗 TeslaAPI 13 Don't charge NCC-1701-D because vehicle.stopAskingToStartCharging == True
Jun 11 13:21:43 TWCManager python3[28742]: 13:21:43 🚗 TeslaAPI 13 Don't charge NCC-74656 because vehicle.stopAskingToStartCharging == True

I'll keep watching it, but this seems to solve my issue!

So in conclusion, I think these lines should be removed or commented out to prevent sending charge_start every minute:

TWCManager/lib/TWCManager/TWCSlave.py

Lines 546 to 559 in b4d1536

	elif self.reportedAmpsActual >= 1.0:
	# At least one plugged in car is successfully charging. We don't
	# know which car it is, so we must set
	# vehicle.stopAskingToStartCharging = False on all vehicles such
	# that if any vehicle is not charging without us calling
	# car_api_charge(False), we'll try to start it charging again at
	# least once. This probably isn't necessary but might prevent
	# some unexpected case from never starting a charge. It also
	# seems less confusing to see in the output that we always try
	# to start API charging after the car stops taking a charge.
	for vehicle in self.master.getModuleByName(
	"TeslaAPI"
	).getCarApiVehicles():
	vehicle.stopAskingToStartCharging = False

[RichieB2B]

I'm glad we found where the current logic fails for you.

I looked at the code again and I can't figure out why we don't have the same issue. The if in line 546 is True while charging so that means stopAskingToStartCharging is set to False constantly. This breaks the whole stopAskingToStartCharging mechanism just like you reported.

@MikeBishop Can you see how this is supposed to work?

[RichieB2B]

I see what the problem is now. During a charge the quoted code indeed resets stopAskingToStartCharging constantly. When there is only one TWC slave there is no need to ask the cars to start charging during a charge. @blach has 2 TWC slaves though, so during a charge of slave A the idle slave B will keep asking the cars to start charging.

I think there are not too many TWCManager users with two or more TWC slaves. It seems this logic has been broken for a long time if not forever.

Removing the code completely like @blach did seems right. Or we could add a conditional self.master.countSlaveTWC() < 2 to the elif and keep it for the single TWC installs.

[MikeBishop]

Or we could add conditions like the case above, so that it triggers when any TWC starts charging, not continuously while charging.

But I suspect this isn't needed and can just be removed.

[blach]

Yeah, I also think this has been broken for a long time, but it never really mattered because the legacy Tesla owner API didn't put any limits on the number of charge commands.

I'm glad you were able to trace the problem.

[blach]

Today I ran into another rate limit:

One of the cars was not at home, so I think car_api_charge caused update_location and in turn update_vehicle_data in TeslaAPI.py to be called every minute until it returned HTTP status 429.

I see this in the log:

Jun 12 18:57:22 TWCManager python3[30367]: 18:57:22 urllib3.co 10 https://debianvm1:4443 "GET /api/1/vehicles/<vin_redacted>/vehicle_data?endpoints=location_data%3Bcharge_state%3Bdrive_state HTTP/1.1" 429 49

According to Tesla's website, "Device data" limit is 200 requests / vehicle / day.

So I now set the default value of the cacheTime parameter of update_location and update_vehicle_data to 60*5 instead of 60 here:

TWCManager/lib/TWCManager/Vehicle/TeslaAPI.py

Line 1477 in b4d1536

def update_location(self, cacheTime=60):

and here:

TWCManager/lib/TWCManager/Vehicle/TeslaAPI.py

Line 1488 in b4d1536

def update_vehicle_data(self, cacheTime=60):

This should only call the API endpoint up to 12 times per hour, which should make it stay below the 200 requests / day.

[blach]

I just saw that there is a backoff mechanism that should be triggered when the API returns 429.

Unfortunately, update_vehicle_data and get_car_api do not seem to look at getCarApiRetryRemaining etc. and always just send the request.

[RichieB2B]

get_car_api() calls self.ready() which does the check for getCarApiRetryRemaining(). And car_api_charge() calls vehicle.ready() as well. So the backoff mechanism should be respected when a 429 response is received.

[blach]

I looked at the code:

In get_car_api, when req.status_code == 429, only vehicle.errorCount is set to 30 and the function returns after that.

updateCarApiLastErrorTime is not called in this case, so vehicle.lastErrorTime is not set.

vehicle.ready does call getCarApiRetryRemaining as you say, but that only checks vehicle.lastErrorTime (which is not set) and not vehicle.errorCount (which is set to 30).

So I think that's why the backoff mechanism isn't triggered.

Correct me if I'm wrong.

[blach]

By the way: I still think that update_vehicle_data should cache its result for 5 minutes instead of only 1 minute to not exceed the 200 / vehicle / day device data limit.

[RichieB2B]

You are right, I've added that to #589 now.

It is wakeVehicle() that explicitly checks for 429 return code without setting updateCarApiLastErrorTime(), car_api_charge() actually calls it for all encountered errors:

TWCManager/lib/TWCManager/Vehicle/TeslaAPI.py

Lines 770 to 782 in b4d1536

	# Start charge failed with an error I
	# haven't seen before, so wait
	# carApiErrorRetryMins mins before trying again.
	logger.info(
	'ERROR "'
	+ reason
	+ '" when trying to '
	+ startOrStop
	+ " car charging via Tesla car API. Will try again later."
	+ "\nIf this error persists, please file an issue at https://github.com/ngardiner/TWCManager/ with a copy of this error.",
	)
	result = "error"
	self.updateCarApiLastErrorTime(vehicle)

[blach]

I'm talking about these lines in get_car_api, (not car_api_charge):

TWCManager/lib/TWCManager/Vehicle/TeslaAPI.py

Lines 1435 to 1438 in b4d1536

	elif req.status_code == 429:
	# We're explicitly being told to back off
	self.errorCount = max(30, self.errorCount)
	return False, None

There should be a call to self.carapi.updateCarApiLastErrorTime(self) after self.errorCount = max(30, self.errorCount)

But yeah, wakeVehicle has the same issue.

[RichieB2B]

I indeed missed the 429 in get_car_api(). I've added a self.updateCarApiLastErrorTime() in this function now as well.