Optimize logging (#41)

* Move print statements to logger

* Add external log location for addon usage

* Add more detailed logs for debug

* Bump version

.gitignore

@@ -2,3 +2,5 @@
 venv
 src/settings.dev.json
 .env
+/src/volvo2mqtt.log
+/src/volvo2mqtt.log.1

src/Dockerfile

@@ -15,6 +15,7 @@ RUN pip install -r requirements.txt
 
 # copy the content of the local src directory to the working directory
 COPY / .
+RUN chmod a+x /volvoAAOS2mqtt/run.sh
 
 # command to run on container start
-CMD [ "python", "-u", "./main.py" ]
+CMD [ "/volvoAAOS2mqtt/run.sh" ]

src/config.yaml

@@ -1,10 +1,12 @@
 name: "Volvo2Mqtt"
 description: "Volvo AAOS MQTT bridge"
-version: "1.6.0"
+version: "1.6.2"
 slug: "volvo2mqtt"
 init: false
 url: "https://github.com/Dielee/volvo2mqtt"
 apparmor: true
+map: 
+  - addons:rw
 options:
   updateInterval: 300
   babelLocale: null

src/const.py

@@ -1,6 +1,6 @@
 from config import settings
 
-VERSION = "v1.6.0"
+VERSION = "v1.6.2"
 
 OAUTH_URL = "https://volvoid.eu.volvocars.com/as/token.oauth2"
 VEHICLES_URL = "https://api.volvocars.com/connected-vehicle/v1/vehicles"
@@ -19,6 +19,8 @@ ENGINE_STATE_URL = "https://api.volvocars.com/connected-vehicle/v2/vehicles/{0}/
 BATTERY_CHARGE_STATE_URL = "https://api.volvocars.com/connected-vehicle/v2/vehicles/{0}/battery-charge-level"
 FUEL_STATE_URL = "https://api.volvocars.com/connected-vehicle/v2/vehicles/{0}/fuel"
 STATISTICS_URL = "https://api.volvocars.com/connected-vehicle/v2/vehicles/{0}/statistics"
+DISTANCE_TO_EMPTY_URL = "https://api.volvocars.com/extended-vehicle/v1/vehicles/{0}/resources/distanceToEmpty"
+WASHER_FLUID_LEVEL_URL = "https://api.volvocars.com/extended-vehicle/v1/vehicles/{0}/resources/washerFluidLevel"
 
 units = {
             "en_GB": {
@@ -79,5 +81,7 @@ supported_entities = [
                         {"name": "Engine State", "domain": "sensor", "id": "engine_state", "icon": "engine", "url": ENGINE_STATE_URL},
                         {"name": "Fuel Level", "domain": "sensor", "id": "fuel_level", "unit": "liters", "icon": "fuel", "url": FUEL_STATE_URL},
                         {"name": "Average Fuel Consumption", "domain": "sensor", "id": "average_fuel_consumption", "unit": "liters", "icon": "fuel", "url": STATISTICS_URL},
-                        {"name": "Average Speed", "domain": "sensor", "id": "average_speed", "unit": "km/h" if not units.get(settings["babelLocale"]) else units[settings["babelLocale"]]["average_speed"]["unit"], "icon": "speedometer", "url": STATISTICS_URL}
+                        {"name": "Average Speed", "domain": "sensor", "id": "average_speed", "unit": "km/h" if not units.get(settings["babelLocale"]) else units[settings["babelLocale"]]["average_speed"]["unit"], "icon": "speedometer", "url": STATISTICS_URL},
+                        {"name": "Distance to Empty", "domain": "sensor", "id": "distance_to_empty", "unit": "km" if not units.get(settings["babelLocale"]) else units[settings["babelLocale"]]["odometer"]["unit"], "icon": "map-marker-distance", "url": DISTANCE_TO_EMPTY_URL},
+                        {"name": "Washer Fluid Level", "domain": "sensor", "id": "washer_fluid_level", "icon": "wiper-wash", "url": WASHER_FLUID_LEVEL_URL},
 ]

src/main.py

@@ -1,11 +1,14 @@
+import logging
 from volvo import authorize
 from mqtt import update_loop, connect
 from const import VERSION
-from util import set_tz
+from util import set_tz, setup_logging
+
 
 if __name__ == '__main__':
-    print("Starting volvo2mqtt version " + VERSION)
     set_tz()
+    setup_logging()
+    logging.info("Starting volvo2mqtt version " + VERSION)
     authorize()
     connect()
     update_loop()

src/mqtt.py

@@ -1,3 +1,4 @@
+import logging
 import time
 import paho.mqtt.client as mqtt
 import json
@@ -16,6 +17,7 @@ subscribed_topics = []
 assumed_climate_state = {}
 last_data_update = None
 climate_timer = {}
+door_status = {}
 
 
 def connect():
@@ -47,41 +49,60 @@ def on_connect(client, userdata, flags, rc):
 
 
 def on_disconnect(client, userdata,  rc):
-    print("MQTT disconnected, reconnecting automatically")
+    logging.warning("MQTT disconnected, reconnecting automatically")
 
 
 def on_message(client, userdata, msg):
     try:
         vin = msg.topic.split('/')[2].split('_')[0]
     except IndexError:
-        print("Error - Cannot get vin from MQTT topic!")
+        logging.error("Error - Cannot get vin from MQTT topic!")
         return None
 
     payload = msg.payload.decode("UTF-8")
     if "climate_status" in msg.topic:
-        global assumed_climate_state, climate_timer
+        global assumed_climate_state, climate_timer, door_status
         if payload == "ON":
-            api_thread = Thread(target=volvo.api_call, args=(CLIMATE_START_URL, "POST", vin))
+            # Start the api call in another thread for HA performance
-            api_thread.start()
+            Thread(target=volvo.api_call, args=(CLIMATE_START_URL, "POST", vin)).start()
-            assumed_climate_state[vin] = "ON"
+
+            # Start door check thread to turn off climate if driver door is opened
+            door_thread = Thread(target=volvo.check_door_status, args=(vin, ))
+            door_thread.start()
+            door_status[vin] = door_thread
             # Starting timer to disable climate after 30 mins
+
             climate_timer[vin] = Timer(30 * 60, volvo.disable_climate, (vin, ))
             climate_timer[vin].start()
+            # Set and update switch status
+
+            assumed_climate_state[vin] = "ON"
             update_car_data()
         elif payload == "OFF":
-            api_thread = Thread(target=volvo.api_call, args=(CLIMATE_STOP_URL, "POST", vin))
+            # Start the api call in another thread for HA performance
-            api_thread.start()
+            Thread(target=volvo.api_call, args=(CLIMATE_STOP_URL, "POST", vin)).start()
-            assumed_climate_state[vin] = "OFF"
+
-            # Stop timer if active
+            # Stop door check thread if running
+            if door_status[vin].is_alive():
+                door_status[vin].do_run = False
+
+            # Stop climate timer if active
             if climate_timer[vin].is_alive():
                 climate_timer[vin].cancel()
+
+            # Set and update switch status
+            assumed_climate_state[vin] = "OFF"
             update_car_data()
     elif "lock_status" in msg.topic:
         if payload == "LOCK":
             volvo.api_call(CAR_LOCK_URL, "POST", vin)
+
+            # Force set unlocked state in HA because of slow api response
             update_car_data(True, {"entity_id": "lock_status", "vin": vin, "state": "LOCKED"})
         elif payload == "UNLOCK":
             volvo.api_call(CAR_UNLOCK_URL, "POST", vin)
+
+            # Force set unlocked state in HA because of slow api response
             update_car_data(True, {"entity_id": "lock_status", "vin": vin, "state": "UNLOCKED"})
     elif "update_data" in msg.topic:
         if payload == "PRESS":
@@ -91,10 +112,10 @@ def on_message(client, userdata, msg):
 def update_loop():
     create_ha_devices()
     while True:
-        print("Sending mqtt update...")
+        logging.info("Sending mqtt update...")
         send_heartbeat()
         update_car_data()
-        print("Mqtt update done. Next run in " + str(settings["updateInterval"]) + " seconds.")
+        logging.info("Mqtt update done. Next run in " + str(settings["updateInterval"]) + " seconds.")
         time.sleep(settings["updateInterval"])
 
 

src/run.sh

@@ -0,0 +1,4 @@
+#!/bin/bash
+export IS_HA_ADDON="true"
+
+python -u main.py

src/util.py

@@ -1,11 +1,46 @@
+import logging
 import pytz
 import os
+import sys
+from logging import handlers
+from datetime import datetime
 from const import units
 from config import settings
+from pathlib import Path
 
 TZ = None
 
 
+def setup_logging():
+    log_location = "volvo2mqtt.log"
+    if os.environ.get("IS_HA_ADDON"):
+        check_existing_folder()
+        log_location = "/addons/volvo2mqtt/log/volvo2mqtt.log"
+
+    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',
+        '%b %d %H:%M:%S')
+    file_log_handler.setFormatter(formatter)
+    logger = logging.getLogger()
+
+    console_log_handler = logging.StreamHandler(sys.stdout)
+    console_log_handler.setFormatter(formatter)
+
+    logger.addHandler(console_log_handler)
+    logger.addHandler(file_log_handler)
+
+    logger.setLevel(logging.INFO)
+    if "debug" in settings:
+        if settings["debug"]:
+            logger.setLevel(logging.DEBUG)
+
+
+def check_existing_folder():
+    Path("/addons/volvo2mqtt/log/").mkdir(parents=True, exist_ok=True)
+
+
 def keys_exists(element, *keys):
     """"
     Check if *keys (nested) exists in `element` (dict).
@@ -43,3 +78,4 @@ def convert_metric_values(value):
         return round((float(value) / divider), 2)
     else:
         return value
+

src/volvo.py

@@ -1,13 +1,17 @@
+import logging
+
 import requests
 import mqtt
 import util
+import time
+from threading import Thread, currentThread
 from datetime import datetime, timedelta
 from config import settings
 from babel.dates import format_datetime
 from const import charging_system_states, charging_connection_states, door_states, window_states, \
     OAUTH_URL, VEHICLES_URL, VEHICLE_DETAILS_URL, RECHARGE_STATE_URL, CLIMATE_START_URL, \
     WINDOWS_STATE_URL, LOCK_STATE_URL, TYRE_STATE_URL, supported_entities, BATTERY_CHARGE_STATE_URL, \
-    STATISTICS_URL
+    STATISTICS_URL, CLIMATE_STOP_URL
 
 session = requests.Session()
 session.headers = {
@@ -53,7 +57,7 @@ def authorize():
 
 
 def refresh_auth():
-    print("Refreshing credentials")
+    logging.info("Refreshing credentials")
     global refresh_token
     headers = {
         "authorization": "Basic aDRZZjBiOlU4WWtTYlZsNnh3c2c1WVFxWmZyZ1ZtSWFEcGhPc3kxUENhVXNpY1F0bzNUUjVrd2FKc2U0QVpkZ2ZJZmNMeXc=",
@@ -65,7 +69,13 @@ def refresh_auth():
         "grant_type": "refresh_token",
         "refresh_token": refresh_token
     }
+
+    try:
         auth = requests.post(OAUTH_URL, data=body, headers=headers)
+    except requests.exceptions.RequestException as e:
+        logging.error("Error refreshing credentials data: " + str(e))
+        return None
+
     if auth.status_code == 200:
         data = auth.json()
         session.headers.update({'authorization': "Bearer " + data["access_token"]})
@@ -102,16 +112,14 @@ def get_vehicles():
         raise Exception("No vehicle found, exiting application!")
     else:
         initialize_climate(vins)
-        print("Vin: " + str(vins) + " found!")
+        logging.info("Vin: " + str(vins) + " found!")
 
 
 def get_vehicle_details(vin):
     response = session.get(VEHICLE_DETAILS_URL.format(vin), timeout=15)
     if response.status_code == 200:
         data = response.json()["data"]
-        if "debug" in settings:
+        logging.debug(response.text)
-            if settings["debug"]:
-                print(response.text)
         device = {
             "identifiers": [f"volvoAAOS2mqtt_{vin}"],
             "manufacturer": "Volvo",
@@ -149,10 +157,10 @@ def check_supported_endpoints():
                 state = ""
 
             if state is not None:
-                print("Success! " + entity["name"] + " is supported by your vehicle.")
+                logging.info("Success! " + entity["name"] + " is supported by your vehicle.")
                 supported_endpoints[vin].append(entity)
             else:
-                print("Failed, " + entity["name"] + " is unfortunately not supported by your vehicle.")
+                logging.info("Failed, " + entity["name"] + " is unfortunately not supported by your vehicle.")
 
 
 def initialize_climate(vins):
@@ -161,11 +169,25 @@ def initialize_climate(vins):
 
 
 def disable_climate(vin):
-    print("Turning climate off by timer!")
+    logging.info("Turning climate off by timer!")
+    mqtt.door_status[vin].do_run = False
     mqtt.assumed_climate_state[vin] = "OFF"
     mqtt.update_car_data()
 
 
+def check_door_status(vin):
+    t = currentThread()
+    while getattr(t, "do_run", True):
+        lock_door_left = api_call(LOCK_STATE_URL, "GET", vin, "door_front_left", True)
+        lock_door_right = api_call(LOCK_STATE_URL, "GET", vin, "door_front_right", True)
+        if lock_door_left == "ON" or lock_door_right == "ON":
+            Thread(target=api_call, args=(CLIMATE_STOP_URL, "POST", vin)).start()
+            mqtt.assumed_climate_state[vin] = "OFF"
+            mqtt.update_car_data()
+            break
+        time.sleep(5)
+
+
 def api_call(url, method, vin, sensor_id=None, force_update=False):
     global token_expires_at
     if datetime.now(util.TZ) >= token_expires_at:
@@ -178,36 +200,40 @@ def api_call(url, method, vin, sensor_id=None, force_update=False):
             # Exception caught while getting data from volvo api, doing nothing
             return None
     elif method == "GET":
-        print("Starting " + method + " call against " + url)
+        logging.debug("Starting " + method + " call against " + url)
         try:
             response = session.get(url.format(vin), timeout=15)
         except requests.exceptions.RequestException as e:
-            print("Error getting data: " + str(e))
+            logging.error("Error getting data: " + str(e))
-            return ""
+            return None
     elif method == "POST":
-        print("Starting " + method + " call against " + url)
+        logging.debug("Starting " + method + " call against " + url)
         try:
             response = session.post(url.format(vin), timeout=20)
         except requests.exceptions.RequestException as e:
-            print("Error getting data: " + str(e))
+            logging.error("Error getting data: " + str(e))
-            return ""
+            return None
     else:
-        print("Unkown method posted: " + method + ". Returning nothing")
+        logging.error("Unkown method posted: " + method + ". Returning nothing")
-        return ""
+        return None
 
+    logging.debug("Response status code: " + str(response.status_code))
     if response.status_code == 200:
         data = response.json()
-        if "debug" in settings:
+        logging.debug(response.text)
-            if settings["debug"]:
-                print(response.text)
     else:
+        logging.debug(response.text)
         if url == CLIMATE_START_URL and response.status_code == 503:
-            print("Car in use, cannot start pre climatization")
+            logging.warning("Car in use, cannot start pre climatization")
             mqtt.assumed_climate_state[vin] = "OFF"
             mqtt.update_car_data()
+        elif "extended-vehicle" in url and response.status_code == 403:
+            # Suppress 403 errors for unsupported extended-vehicle api cars
+            logging.debug("Suppressed 403 for extended-vehicle API")
+            return None
         else:
-            print("API Call failed. Status Code: " + str(response.status_code) + ". Error: " + response.text)
+            logging.error("API Call failed. Status Code: " + str(response.status_code) + ". Error: " + response.text)
-        return ""
+        return None
     return parse_api_data(data, sensor_id)
 
 
@@ -215,26 +241,26 @@ def cached_request(url, method, vin, force_update=False):
     global cached_requests
     if not util.keys_exists(cached_requests, vin + "_" + url):
         # No API Data cached, get fresh data from API
-        print("Starting " + method + " call against " + url)
+        logging.debug("Starting " + method + " call against " + url)
         try:
             response = session.get(url.format(vin), timeout=15)
         except requests.exceptions.RequestException as e:
-            print("Error getting data: " + str(e))
+            logging.error("Error getting data: " + str(e))
             return None
 
         data = {"response": response, "last_update": datetime.now(util.TZ)}
         cached_requests[vin + "_" + url] = data
     else:
-        if (datetime.now(util.TZ) - cached_requests[vin + "_" + url]["last_update"]).total_seconds() >= settings[
+        if (datetime.now(util.TZ) - cached_requests[vin + "_" + url]["last_update"]).total_seconds() \
-            "updateInterval"] \
+                >= settings["updateInterval"] or (force_update and
-                or (force_update and (
+                                                  (datetime.now(util.TZ) - cached_requests[vin + "_" + url]
-                datetime.now(util.TZ) - cached_requests[vin + "_" + url]["last_update"]).total_seconds() >= 2):
+                                                      ["last_update"]).total_seconds() >= 2):
             # Old Data in Cache, or force mode active, updating
-            print("Starting " + method + " call against " + url)
+            logging.debug("Starting " + method + " call against " + url)
             try:
                 response = session.get(url.format(vin), timeout=15)
             except requests.exceptions.RequestException as e:
-                print("Error getting data: " + str(e))
+                logging.error("Error getting data: " + str(e))
                 return None
             data = {"response": response, "last_update": datetime.now(util.TZ)}
             cached_requests[vin + "_" + url] = data
@@ -380,5 +406,10 @@ def parse_api_data(data, sensor_id=None):
                                "latitude": raw_data["coordinates"][1],
                                "gps_accuracy": 1}
         return coordinates
+    elif sensor_id == "distance_to_empty":
+        return util.convert_metric_values(data["distanceToEmpty"]["value"]) \
+            if util.keys_exists(data, "distanceToEmpty") else None
+    elif sensor_id == "washer_fluid_level":
+        return data["washerFluidLevel"]["value"] if util.keys_exists(data, "washerFluidLevel") else None
     else:
         return None