Entities not created if FIN and VIN do not match

[JonathanCasey]

I ran into an issue when setting this up where my car would be added, but there would be no entities. I managed to trace this down to my FIN and VIN being different, and the data not being loaded via the FIN. I am in the US, which I suspect is a factor in this.

The good news is that there is already a workaround for anyone who runs into this. By turning on debug logs in my HA configuration, the unrecognized FIN is reported. This FIN can be copied into the "VINs excluded" list in the integration options in HA. Restarting the integration and HA will let the car data load complete, and subsequently the entities will be created.

I am wondering if there is a way to update the logic so this will just work without a new user needing to turn on debug logging to figure out that they need to add the FIN to the exclusion list.

As I looked into this, I noticed that async_setup_entry() in __init__.py uses the FIN for everything in this block, which adds a first car to the list of cars using the FIN. Later, a "second" car is added by the vin in Client._process_assigned_vehicles() in client.py, but this is really the same car. The FIN seems to never be able to complete entry setup, so this block at the end of Client._process_assigned_vehicle() always sets load_complete to False if at least 1 car does not complete, and therefore never executes the callback _on_dataload_complete() that points to MercedesMeContext.on_dataload_complete() in order to create the entities.

Here is my HA log with the logger set for debug and filtered to only show items from mbapi2020. I've redacted anything that might have been personal information. Critically, I noted which items were the <FIN> and which were the <VIN> for the single vehicle I have and confirmed via the debug json output of masterdata in async_setup_entry() in __init__.py.:

2022-01-22 17:57:15 INFO (MainThread) [custom_components.mbapi2020.oauth] Start request PIN <email>
2022-01-22 17:57:33 DEBUG (MainThread) [custom_components.mbapi2020.oauth] Start _save_token_info() to /config/.mercedesme-token-cache
2022-01-22 17:57:33 DEBUG (MainThread) [custom_components.mbapi2020.config_flow] Token received
2022-01-22 17:57:33 DEBUG (MainThread) [custom_components.mbapi2020.oauth] Start async_get_cached_token()
2022-01-22 17:57:33 DEBUG (MainThread) [custom_components.mbapi2020.oauth] Start async_get_cached_token()
2022-01-22 17:57:34 DEBUG (MainThread) [custom_components.mbapi2020.client] {}
2022-01-22 17:57:34 DEBUG (MainThread) [custom_components.mbapi2020.oauth] Start async_get_cached_token()
2022-01-22 17:57:34 DEBUG (MainThread) [custom_components.mbapi2020.client] {}
2022-01-22 17:57:34 DEBUG (MainThread) [custom_components.mbapi2020.oauth] Start async_get_cached_token()
2022-01-22 17:57:35 DEBUG (MainThread) [custom_components.mbapi2020] RCP supported for car <FIN>: False
2022-01-22 17:57:35 DEBUG (MainThread) [custom_components.mbapi2020] Init - car added - <FIN>
2022-01-22 17:57:35 DEBUG (MainThread) [custom_components.mbapi2020] Remove check: <device_entry.id>, <FIN>
2022-01-22 17:57:35 DEBUG (MainThread) [custom_components.mbapi2020.oauth] Start async_get_cached_token()
2022-01-22 17:57:35 INFO (MainThread) [custom_components.mbapi2020.websocket] Connecting to wss://websocket-prod.risingstars-amap.daimler.com/ws
2022-01-22 17:57:35 INFO (MainThread) [custom_components.mbapi2020.websocket] Connected to mercedes websocket at wss://websocket-prod.risingstars-amap.daimler.com/ws
2022-01-22 17:57:35 DEBUG (MainThread) [custom_components.mbapi2020.websocket] Got notification: debugMessage
2022-01-22 17:57:35 DEBUG (MainThread) [custom_components.mbapi2020.client] debugMessage - Data: Registering User with ciamID: <ciamID> and App-UUID: <app uuid>
2022-01-22 17:57:35 DEBUG (MainThread) [custom_components.mbapi2020.websocket] Got notification: debugMessage
2022-01-22 17:57:35 DEBUG (MainThread) [custom_components.mbapi2020.client] debugMessage - Data: app twin actor was initialized
2022-01-22 17:57:35 DEBUG (MainThread) [custom_components.mbapi2020.websocket] Got notification: assigned_vehicles
2022-01-22 17:57:35 DEBUG (MainThread) [custom_components.mbapi2020.client] Start _process_assigned_vehicles
2022-01-22 17:57:35 DEBUG (MainThread) [custom_components.mbapi2020.client] _process_assigned_vehicles - <FIN> - False - Counter({'f': 0, 'p': 0}) - 388
2022-01-22 17:57:35 DEBUG (MainThread) [custom_components.mbapi2020.client] _process_assigned_vehicles - <VIN> - False - Counter({'f': 0, 'p': 0}) - 1642892255842
2022-01-22 17:57:35 DEBUG (MainThread) [custom_components.mbapi2020.websocket] Got notification: apptwin_pending_command_request
2022-01-22 17:57:36 DEBUG (MainThread) [custom_components.mbapi2020.websocket] Got notification: vepUpdates
2022-01-22 17:57:36 DEBUG (MainThread) [custom_components.mbapi2020.client] Start _process_vep_updates
2022-01-22 17:57:36 DEBUG (MainThread) [custom_components.mbapi2020.client] Full Update. <VIN>
2022-01-22 17:57:36 DEBUG (MainThread) [custom_components.mbapi2020.client] get_car_values Odometer for <VIN> called
2022-01-22 17:57:36 DEBUG (MainThread) [custom_components.mbapi2020.client] get_car_values Tires for <VIN> called
2022-01-22 17:57:36 DEBUG (MainThread) [custom_components.mbapi2020.client] get_car_values Doors for <VIN> called
2022-01-22 17:57:36 DEBUG (MainThread) [custom_components.mbapi2020.client] get_car_values Location for <VIN> called
2022-01-22 17:57:36 DEBUG (MainThread) [custom_components.mbapi2020.client] get_car_values BinarySensors for <VIN> called
2022-01-22 17:57:36 DEBUG (MainThread) [custom_components.mbapi2020.client] get_car_values Windows for <VIN> called
2022-01-22 17:57:36 DEBUG (MainThread) [custom_components.mbapi2020.client] get_car_values Electric for <VIN> called
2022-01-22 17:57:36 DEBUG (MainThread) [custom_components.mbapi2020.client] get_car_values Auxheat for <VIN> called
2022-01-22 17:57:36 DEBUG (MainThread) [custom_components.mbapi2020.client] _process_vep_updates - <FIN> - complete: False - Counter({'f': 0, 'p': 0})
2022-01-22 17:57:36 DEBUG (MainThread) [custom_components.mbapi2020.client] _process_vep_updates - <VIN> - complete: True - Counter({'f': 1, 'p': 0})
2022-01-22 17:57:36 DEBUG (MainThread) [custom_components.mbapi2020.client] vepUpdates Sequence: 0
2022-01-22 17:57:39 DEBUG (MainThread) [custom_components.mbapi2020.websocket] Got notification: assigned_vehicles
2022-01-22 17:57:39 DEBUG (MainThread) [custom_components.mbapi2020.client] Start _process_assigned_vehicles
2022-01-22 17:57:39 DEBUG (MainThread) [custom_components.mbapi2020.client] _process_assigned_vehicles - <FIN> - False - Counter({'f': 0, 'p': 0}) - 4390
2022-01-22 17:57:39 DEBUG (MainThread) [custom_components.mbapi2020.client] _process_assigned_vehicles - <VIN> - True - Counter({'f': 1, 'p': 0}) - 3825
2022-01-22 17:57:39 DEBUG (MainThread) [custom_components.mbapi2020.websocket] Got notification: apptwin_pending_command_request

I am unsure what the best way to address this would be, but I hope this is helpful. I can test any changes or get any more data needed, especially if a US tester is required.

Very cool project. Danke!

[ReneNulschDE]

Hi Jonathan,

thanks for this detailed analysis. You're right, this procedure is needed for the US only. I tried different ways in past to overcome this issue with the different VIN/FIN but never came to a stable solution without breaking changes for all the existing US users.

Let me check it again and it is great that you can test possible solutions. Are you a member of the HA-community? If yes, we could use private messages as a comms platform.

could you add the logs after

2022-01-22 17:57:39 DEBUG (MainThread) [custom_components.mbapi2020.client] _process_assigned_vehicles - <FIN> - False - Counter({'f': 0, 'p': 0}) - 4390
2022-01-22 17:57:39 DEBUG (MainThread) [custom_components.mbapi2020.client] _process_assigned_vehicles - <VIN> - True - Counter({'f': 1, 'p': 0}) - 3825

Normally, the code should wait for 30 seconds (4390 and 3825 are the wait times in ms) and then create the entities.

BR
Rene

[JonathanCasey]

Hi Rene,

I see your point. It might be risky to make improvements, but I can test if any ideas work for at least 1 car in the US. It's a start, right?

I ran through initialization again to get more log information, but after waiting a few minutes, the only messages I see in the logs are Got notification: apptwin_pending_command_request every 15 seconds. I never saw it attempt to _process_assigned_vehicles again.

Good idea to chat on the HA-community. My handle is jonathanjcasey. I've sent you a message.

[ReneNulschDE]

Fix implemented with 6849673

needs review and rework as we create unneeded entities and sensors. current fix focus is on preventing breaking changes