Some minor corrections and more checking for exceptions (#267)

* better logging, indicate URL used on API errors, check exceptions in more places to dont kill threads, add option for mqtt logging

* dont force token renew on 5xx errors

* indicate payload on error message to understand better issue #270

* better checking on received update_interval #270

---------

Co-authored-by: Linus Dietz <45101649+Dielee@users.noreply.github.com>

README.md

@@ -141,14 +141,15 @@ Here is what every option means:
 | ------------------------- | :-------: | :-----------------------------------: | :----------: | --------------------------------------------------------------- |
 | `CONF_updateInterval`     | `int`     |                                       | **required** | Update intervall in seconds.                                     |
 | `CONF_babelLocale`        | `string`  |                                       | **required** | Select your country from this [list](https://www.ibm.com/docs/en/radfws/9.7?topic=overview-locales-code-pages-supported). "Locale name" is the column you need!                                        |
-| `CONF_mqtt`               | `json`    | `broker`                              | **required** | Your MQTT Broker IP. Eg. 192.168.0.5.
+| `CONF_mqtt`               | `json`    | `broker`                              | **required** | Your MQTT Broker IP. Eg. 192.168.0.5. |
 | `CONF_mqtt`               | `json`    | `port`                                | 1883         | Your MQTT Broker Port. If no value is given, port 1883 will be used.  |
-| `CONF_mqtt`               | `json`    | `username`                            | optional     | MQTT Username for your broker.
-| `CONF_mqtt`               | `json`    | `password`                            | optional     | MQTT Password for your broker.
-| `CONF_volvoData`          | `json`    | `username`                            | **required** | Normally your email address to login into the Volvo App.
-| `CONF_volvoData`          | `json`    | `password`                            | **required** | Your password to login into the Volvo App.
-| `CONF_volvoData`          | `json`    | `vin`                                 | optional     | A single VIN like "VIN1" or a list of VINs like "["VIN1", "VIN2"]". Leave this empty if you don't know your VIN. The addon will use every car that is tied to your account.
-| `CONF_volvoData`          | `json`    | `vccapikey`                           | **required** | VCCAPIKEY linked with your volvo developer account. Get your Vccapi key from [here](https://developer.volvocars.com/account/). <b>Starting version 1.8.0, it is possible to define multiple keys, like this: `["vccapikey1", "vccapikey2", "vccapikey3", "etc..."]`</b>
+| `CONF_mqtt`               | `json`    | `username`                            | optional     | MQTT Username for your broker. |
+| `CONF_mqtt`               | `json`    | `password`                            | optional     | MQTT Password for your broker. |
+| `CONF_mqtt`               | `json`    | `logging`                             | optional     | Enable MQTT logging (true/false). Default don't enable MQTT log. |
+| `CONF_volvoData`          | `json`    | `username`                            | **required** | Normally your email address to login into the Volvo App. |
+| `CONF_volvoData`          | `json`    | `password`                            | **required** | Your password to login into the Volvo App. |
+| `CONF_volvoData`          | `json`    | `vin`                                 | optional     | A single VIN like "VIN1" or a list of VINs like "["VIN1", "VIN2"]". Leave this empty if you don't know your VIN. The addon will use every car that is tied to your account. |
+| `CONF_volvoData`          | `json`    | `vccapikey`                           | **required** | VCCAPIKEY linked with your volvo developer account. Get your Vccapi key from [here](https://developer.volvocars.com/account/). <b>Starting version 1.8.0, it is possible to define multiple keys, like this: `["vccapikey1", "vccapikey2", "vccapikey3", "etc..."]`</b> |
 | `CONF_debug`              | `string`  |                                       | optional     | Debug option (true/false). Normally you don't need this. |
 | `TZ`                      | `string`  |                                       | **required** | Container timezone eg "Europe/Berlin" from [here](https://docs.diladele.com/docker/timezones.html)|
 

src/mqtt.py

@@ -6,6 +6,7 @@ import volvo
 import util
 import os
 import requests
+import threading
 from threading import Thread, Timer
 from datetime import datetime
 from babel.dates import format_datetime
@@ -27,6 +28,14 @@ def connect():
     client = mqtt.Client("volvoAAOS2mqtt") if os.environ.get("IS_HA_ADDON") \
         else mqtt.Client("volvoAAOS2mqtt_" + settings.volvoData["username"].replace("+", ""))
 
+    if "logging" in settings["mqtt"] and settings["mqtt"]["logging"]:
+        mqtt_logger = logging.getLogger("mqtt")
+        client.enable_logger(mqtt_logger)
+    
+    client.on_message = safe_on_message
+    client.on_disconnect = on_disconnect
+    client.on_connect = on_connect
+
     client.will_set(availability_topic, "offline", 0, False)
     if settings["mqtt"]["username"] and settings["mqtt"]["password"]:
         client.username_pw_set(settings["mqtt"]["username"], settings["mqtt"]["password"])
@@ -37,11 +46,9 @@ def connect():
             if conf_port > 0:
                 port = settings["mqtt"]["port"]
     client.connect(settings["mqtt"]["broker"], port)
+    
     client.loop_start()
     client.subscribe("volvoAAOS2mqtt/otp_code")
-    client.on_message = on_message
-    client.on_disconnect = on_disconnect
-    client.on_connect = on_connect
 
     global mqtt_client
     mqtt_client = client
@@ -51,7 +58,7 @@ def create_otp_input():
     state_topic = otp_mqtt_topic + "/state"
     config = {
         "name": "Volvo OTP",
-        "object_id": f"volvo_otp",
+        "object_id": "volvo_otp",
         "schema": "state",
         "command_topic": otp_mqtt_topic,
         "state_topic": state_topic,
@@ -128,6 +135,10 @@ def send_car_images(vin, data, device):
 
 
 def on_connect(client, userdata, flags, rc):
+    # set a better name for the mqtt_loop Thread
+    threading.current_thread().name = 'mqtt_thread'
+    logging.info("MQTT connected")
+    
     send_heartbeat()
     if len(subscribed_topics) > 0:
         for topic in subscribed_topics:
@@ -135,9 +146,16 @@ def on_connect(client, userdata, flags, rc):
 
 
 def on_disconnect(client, userdata, rc):
-    logging.warning("MQTT disconnected, reconnecting automatically")
+    logging.warning(f"MQTT disconnected, reconnecting automatically rc={rc}")
 
 
+def safe_on_message(client, userdata, msg):
+    try:
+        on_message(client, userdata, msg)
+    except Exception as error:
+        logging.error(f"Exception {error} processing received message on topic {msg.topic}")
+        return None
+        
 def on_message(client, userdata, msg):
     payload = msg.payload.decode("UTF-8")
     if msg.topic == otp_mqtt_topic:
@@ -152,7 +170,7 @@ def on_message(client, userdata, msg):
         try:
             vin = msg.topic.split('/')[2].split('_')[0]
         except IndexError:
-            logging.error("Error - Cannot get vin from MQTT topic!")
+            logging.error(f"Error - Cannot get vin from MQTT topic : {msg.topic}!")
             return None
 
     if "climate_status" in msg.topic:
@@ -169,17 +187,20 @@ def on_message(client, userdata, msg):
         if payload == "PRESS":
             update_car_data(True)
     elif "update_interval" in msg.topic:
-        update_interval = int(payload)
-        if update_interval >= 60 or update_interval == -1:
-            settings.update({"updateInterval": int(update_interval)})
-        else:
-            logging.warning("Interval " + str(update_interval) + " seconds is to low. Doing nothing!")
-        update_car_data()
+        try:
+            update_interval = int(payload)
+            if update_interval >= 60 or update_interval == -1:
+               settings.update({"updateInterval": int(update_interval)})
+            else:
+                logging.warning(f"Interval {update_interval} seconds is to low. Doing nothing!")
+            update_car_data()
+        except ValueError as error:
+            logging.error(f"Unable to change update_interval {error} payload={payload}") 
     elif "schedule" in msg.topic:
         try:
             d = json.loads(payload)
         except ValueError as e:
-            logging.error("Can't set timer. Error: " + str(e))
+            logging.error(f"Can't set timer. Error: {e}, payload={payload}")
             return None
 
         if d["mode"] == "timer":
@@ -197,13 +218,13 @@ def start_climate_timer(d, vin):
         start_datetime = local_datetime.replace(hour=hour, minute=minute, second=0)
         timer_seconds = (start_datetime - local_datetime).total_seconds()
     except Exception as e:
-        logging.error("Error creating climate timer: " + str(e))
+        logging.error(f"Error creating climate timer: {e}")
         return None
 
     if timer_seconds > 0:
         Timer(timer_seconds, activate_climate_timer, (vin, start_datetime.isoformat(),)).start()
         active_schedules[vin]["timers"].append(start_datetime.isoformat())
-        logging.debug("Climate timer set to " + str(start_datetime))
+        logging.debug(f"Climate timer set to {start_datetime}")
         update_car_data()
     else:
         logging.warning("Timer can not be set. Unusable start time entered")
@@ -211,28 +232,28 @@ def start_climate_timer(d, vin):
 
 def unlock_car(vin):
     # Start the api call in another thread for HA performance
-    Thread(target=volvo.api_call, args=(CAR_UNLOCK_URL, "POST", vin)).start()
+    Thread(target=volvo.api_call, args=(CAR_UNLOCK_URL, "POST", vin), name="unlock_car_thread").start()
 
     # Force set unlocking state
     update_car_data(False, {"entity_id": "lock_status", "vin": vin, "state": "UNLOCKING"})
     # Fetch API lock state until unlocking finished
-    Thread(target=volvo.check_lock_status, args=(vin, "LOCKED")).start()
+    Thread(target=volvo.check_lock_status, args=(vin, "LOCKED"), name="check_lock_status_thread").start()
 
 
 def lock_car(vin):
     # Start the api call in another thread for HA performance
-    Thread(target=volvo.api_call, args=(CAR_LOCK_URL, "POST", vin)).start()
+    Thread(target=volvo.api_call, args=(CAR_LOCK_URL, "POST", vin), name="lock_car_thread").start()
 
     # Force set locking state
     update_car_data(False, {"entity_id": "lock_status", "vin": vin, "state": "LOCKING"})
     # Fetch API lock state until locking finished
-    Thread(target=volvo.check_lock_status, args=(vin, "UNLOCKED")).start()
+    Thread(target=volvo.check_lock_status, args=(vin, "UNLOCKED"), name="check_lock_status_thread").start()
 
 
 def stop_climate(vin):
     global assumed_climate_state, climate_timer, engine_status
     # Start the api call in another thread for HA performance
-    Thread(target=volvo.api_call, args=(CLIMATE_STOP_URL, "POST", vin)).start()
+    Thread(target=volvo.api_call, args=(CLIMATE_STOP_URL, "POST", vin), name="stop_climate_thread").start()
 
     # Stop door check thread if running
     if engine_status[vin].is_alive():
@@ -256,10 +277,10 @@ def activate_climate_timer(vin, start_time):
 def start_climate(vin):
     global assumed_climate_state, climate_timer, engine_status
     # Start the api call in another thread for HA performance
-    Thread(target=volvo.api_call, args=(CLIMATE_START_URL, "POST", vin)).start()
+    Thread(target=volvo.api_call, args=(CLIMATE_START_URL, "POST", vin), name="start_climate_thread").start()
 
     # Start door check thread to turn off climate if driver door is opened
-    check_engine_thread = Thread(target=volvo.check_engine_status, args=(vin,))
+    check_engine_thread = Thread(target=volvo.check_engine_status, args=(vin,), name="check_engine_status_thread")
     check_engine_thread.start()
     engine_status[vin] = check_engine_thread
 
@@ -277,9 +298,12 @@ def update_loop():
     while True:
         if settings["updateInterval"] > 0:
             logging.info("Sending mqtt update...")
-            send_heartbeat()
-            update_car_data()
-            logging.info("Mqtt update done. Next run in " + str(settings["updateInterval"]) + " seconds.")
+            try:
+                send_heartbeat()
+                update_car_data()
+                logging.info(f"Mqtt update done. Next run in {settings['updateInterval']} seconds.")
+            except Exception as error:
+                logging.info(f"Exception {error} in Mqtt update. Next run in {settings['updateInterval']} seconds.")
             time.sleep(settings["updateInterval"])
         else:
             logging.info("Data update is disabled, doing nothing for 30 seconds")
@@ -338,6 +362,7 @@ def update_car_data(force_update=False, overwrite={}):
             else:
                 topic = f"homeassistant/{entity['domain']}/{vin}_{entity['id']}/state"
 
+            logging.info(f"update_car_data {topic} {state}")
             if state or state == 0:
                 mqtt_client.publish(
                     topic,

src/util.py

@@ -71,7 +71,7 @@ def setup_logging():
     logging.Formatter.converter = lambda *args: datetime.now(tz=TZ).timetuple()
     file_log_handler = logging.handlers.RotatingFileHandler(log_location, maxBytes=1000000, backupCount=1)
     formatter = logging.Formatter(
-        '%(asctime)s volvo2mqtt [%(process)d] - %(levelname)s: %(message)s',
+        '%(asctime)s volvo2mqtt [%(threadName)s] [%(process)d] - %(levelname)s: %(message)s',
         '%b %d %H:%M:%S')
     file_log_handler.setFormatter(formatter)
 

src/volvo.py

@@ -47,6 +47,7 @@ def authorize(renew_tokenfile=False):
         except ValueError:
             logging.warning("Detected corrupted token file, restarting auth process")
             authorize(True)
+            return
     else:
         logging.info("Starting login with OTP")
         auth_session = requests.session()
@@ -105,7 +106,7 @@ def authorize(renew_tokenfile=False):
     get_vcc_api_keys()
     get_vehicles()
     check_supported_endpoints()
-    Thread(target=backend_status_loop).start()
+    Thread(target=backend_status_loop,name="backend_status_thread").start()
 
 def continue_auth(auth_session, data):
     next_url = data["_links"]["continueAuthentication"]["href"].replace("http://", "https://") + "?action=continueAuthentication"
@@ -205,10 +206,15 @@ def refresh_auth():
         session.headers.update({"authorization": "Bearer " + refresh_data["access_token"]})
 
         global token_expires_at
-        token_expires_at = datetime.now(util.TZ) + timedelta(seconds=(refresh_data["expires_in"] - 30))
-        refresh_token = refresh_data["refresh_token"]
+        token_expires_at = datetime.now(util.TZ) + timedelta(seconds=(data["expires_in"] - 30))
+        refresh_token = data["refresh_token"]
+        return None
+    elif int(auth.status_code / 100) == 5:
+        # Server error try again later
+        logging.warning("Refreshing credentials failed!: " + str(auth.status_code) + " Message: " + auth.text)
         return None
     else:
+        # TODO check other codes that dont have to force the renew_tokenfile
         logging.warning("Refreshing credentials failed!: " + str(auth.status_code) + " Message: " + auth.text)
         authorize(renew_tokenfile=True)
         return None
@@ -449,27 +455,38 @@ def check_engine_status(vin):
 
 
 def backend_status_loop():
+    logging.debug("backend_status_loop started")
     while True:
-        get_backend_status()
-        # Update every hour
-        time.sleep(3600)
+        last_status = get_backend_status()
+        # Update every hour when not error, 10 minutes when got server error
+        time.sleep(3600 if not last_status.startswith("APIERR_") else 600)
 
 
 def get_backend_status():
     global backend_status
-    response = session.get(API_BACKEND_STATUS, timeout=15)
     try:
-        data = response.json()
-        if util.keys_exists(data, "message"):
-            if data["message"]:
-                backend_status = data["message"]
+        response = session.get(API_BACKEND_STATUS, timeout=15)
+        try:
+            data = response.json()
+            if util.keys_exists(data, "message"):
+                if data["message"]:
+                    backend_status = data["message"]
+                else:
+                    backend_status = "NO_WARNING"
             else:
                 backend_status = "NO_WARNING"
-        else:
-            backend_status = "NO_WARNING"
 
-    except JSONDecodeError as e:
-        backend_status = "NO_WARNING"
+        except JSONDecodeError as e:
+            logging.error(f"Invalid json response from API Backend Status - {response} - {e}")
+            backend_status = "APIERR_INVALID_JSON_RESPONSE"
+            
+    except requests.exceptions.ReadTimeout as e:
+        logging.error(f"API Backend Status - timeout - {e}")
+        backend_status = "APIERR_TIMEOUT"
+    except requests.exceptions.RequestException as e:
+        logging.error(f"API Backend Status - Error - {e}")
+        backend_status = "APIERR_REQUEST_ERROR"
+        
     return backend_status
 
 
@@ -485,28 +502,28 @@ def api_call(url, method, vin, sensor_id=None, force_update=False, key_change=Fa
             # Exception caught while getting data from volvo api, doing nothing
             return None
     elif method == "GET":
-        logging.debug("Starting " + method + " call against " + url)
+        logging.debug(f"Starting {method} call against {url}")
         try:
             response = session.get(url.format(vin), timeout=15)
         except requests.exceptions.RequestException as e:
-            logging.error("Error getting data: " + str(e))
+            logging.error(f"Error getting data: {e} from {url}")
             return None
     elif method == "POST":
-        logging.debug("Starting " + method + " call against " + url)
+        logging.debug(f"Starting {method} call against {url}")
         try:
             response = session.post(url.format(vin), timeout=20)
         except requests.exceptions.RequestException as e:
-            logging.error("Error getting data: " + str(e))
+            logging.error(f"Error getting data from {url} : {e}")
             return None
     else:
-        logging.error("Unkown method posted: " + method + ". Returning nothing")
+        logging.error(f"Unkown method posted: {method}. Returning nothing")
         return None
 
-    logging.debug("Response status code: " + str(response.status_code))
+    logging.debug(f"Response status code: {response.status_code}")
     try:
         data = response.json()
     except JSONDecodeError as e:
-        logging.error("Fetched json decode error, Volvo API seems to return garbage. Skipping update. Error: " + str(e))
+        logging.error(f"Fetched json decode error, Volvo API seems to return garbage. Skipping update. Error: {e}")
         return None
 
     if response.status_code == 200:
@@ -529,9 +546,9 @@ def api_call(url, method, vin, sensor_id=None, force_update=False, key_change=Fa
                 api_call(url, method, vin, sensor_id, force_update, True)
             else:
                 logging.error(
-                    "API Call failed. Status Code: " + str(response.status_code) + ". Error: " + response.text)
+                    f"API Call failed to {url}. Status Code: {response.status_code}. Error: {response.text}")
         else:
-            logging.error("API Call failed. Status Code: " + str(response.status_code) + ". Error: " + response.text)
+            logging.error(f"API Call failed to {url}. Status Code: {response.status_code}. Error: {response.text}")
         return None
 
 
@@ -539,11 +556,11 @@ def cached_request(url, method, vin, force_update=False, key_change=False):
     global cached_requests
     if not util.keys_exists(cached_requests, vin + "_" + url):
         # No API Data cached, get fresh data from API
-        logging.debug("Starting " + method + " call against " + url)
+        logging.debug(f"Starting {method} call against {url}")
         try:
             response = session.get(url.format(vin), timeout=15)
         except requests.exceptions.RequestException as e:
-            logging.error("Error getting data: " + str(e))
+            logging.error(f"Error getting data from {url}: {e}")
             return None
 
         data = {"response": response, "last_update": datetime.now(util.TZ)}
@@ -555,11 +572,11 @@ def cached_request(url, method, vin, force_update=False, key_change=False):
                                                       "last_update"]).total_seconds() >= 2) \
                 or key_change:
             # Old Data in Cache, or force mode active, updating
-            logging.debug("Starting " + method + " call against " + url)
+            logging.debug(f"Starting {method} call against {url}")
             try:
                 response = session.get(url.format(vin), timeout=15)
             except requests.exceptions.RequestException as e:
-                logging.error("Error getting data: " + str(e))
+                logging.error(f"Error getting data from {url} : {e}")
                 return None
             data = {"response": response, "last_update": datetime.now(util.TZ)}
             cached_requests[vin + "_" + url] = data