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.1"
+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.1"
+VERSION = "v1.6.2"
 
 OAUTH_URL = "https://volvoid.eu.volvocars.com/as/token.oauth2"
 VEHICLES_URL = "https://api.volvocars.com/connected-vehicle/v1/vehicles"

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
@@ -48,14 +49,14 @@ 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")
@@ -111,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,3 +1,5 @@
+import logging
+
 import requests
 import mqtt
 import util
@@ -55,7 +57,7 @@ def authorize():
 
 
 def refresh_auth():
-    print("Refreshing credentials")
+    logging.info("Refreshing credentials")
     global refresh_token
     headers = {
         "authorization": "Basic aDRZZjBiOlU4WWtTYlZsNnh3c2c1WVFxWmZyZ1ZtSWFEcGhPc3kxUENhVXNpY1F0bzNUUjVrd2FKc2U0QVpkZ2ZJZmNMeXc=",
@@ -71,7 +73,7 @@ def refresh_auth():
     try:
         auth = requests.post(OAUTH_URL, data=body, headers=headers)
     except requests.exceptions.RequestException as e:
-        print("Error refreshing credentials data: " + str(e))
+        logging.error("Error refreshing credentials data: " + str(e))
         return None
 
     if auth.status_code == 200:
@@ -110,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",
@@ -157,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):
@@ -169,7 +169,7 @@ 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()
@@ -200,38 +200,39 @@ 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 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 None
     else:
-        print("Unkown method posted: " + method + ". Returning nothing")
+        logging.error("Unkown method posted: " + method + ". Returning nothing")
         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 None
     return parse_api_data(data, sensor_id)
 
@@ -240,11 +241,11 @@ 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)}
@@ -255,11 +256,11 @@ def cached_request(url, method, vin, force_update=False):
                                                   (datetime.now(util.TZ) - cached_requests[vin + "_" + url]
                                                       ["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