Add QSA_LOGLEVEL environment variable

docs/src/qsa-api/configuration.md

@@ -6,6 +6,7 @@ QSA web server can be configured thanks to the next environment variables:
 |------------|----------------------------------------|------------------------------------------------------------------------------|
 | Yes        | `QSA_QGISSERVER_URL`                   | QGIS Server URL                                                              |
 | Yes        | `QSA_QGISSERVER_PROJECTS_DIR`          | Storage location on the filesystem for QGIS projects/styles and QSA database |
+| No         | `QSA_LOGLEVEL`                         | Loglevel : DEBUG, INFO (default) or ERROR                                    |
 | No         | `QSA_QGISSERVER_PROJECTS_PSQL_SERVICE` | PostgreSQL service to store QGIS projects                                    |
 | No         | `QSA_QGISSERVER_MONITORING_PORT`       | Connection port for `qsa-plugin`                                             |
 | No         | `QSA_MAPPROXY_PROJECTS_DIR`            | Storage location on the filesystem for MapProxy configuration files          |

qsa-api/qsa_api/cli.py

@@ -19,6 +19,8 @@ def __init__(self, cfg: QSAConfig, monitor: QSAMonitor) -> None:
         self.app.register_blueprint(symbology, url_prefix="/api/symbology")
         self.app.register_blueprint(instances, url_prefix="/api/instances")
 
+        self.app.logger.setLevel(cfg.loglevel)
+
     def run(self):
         self.app.run(host="0.0.0.0", threaded=False)
 

qsa-api/qsa_api/config.py

@@ -1,6 +1,7 @@
 # coding: utf8
 
 import os
+import logging
 from pathlib import Path
 
 
@@ -11,6 +12,17 @@ def is_valid(self) -> bool:
             return True
         return False
 
+    @property
+    def loglevel(self):
+        level = os.environ.get("QSA_LOGLEVEL", "INFO").lower()
+
+        logging_level = logging.INFO
+        if level == "debug":
+            logging_level = logging.DEBUG
+        elif level == "error":
+            logging_level = logging.ERROR
+        return logging_level
+
     @property
     def gdal_pam_proxy_dir(self) -> Path:
         return Path(os.environ.get("GDAL_PAM_PROXY_DIR", ""))

qsa-api/qsa_api/project.py

@@ -1,5 +1,6 @@
 # coding: utf8
 
+import sys
 import shutil
 import sqlite3
 from pathlib import Path
@@ -26,8 +27,8 @@
 )
 
 from .mapproxy import QSAMapProxy
-from .utils import StorageBackend, config
 from .vector import VectorSymbologyRenderer
+from .utils import StorageBackend, config, logger
 from .raster import RasterSymbologyRenderer, RasterOverview
 
 
@@ -64,12 +65,14 @@ def projects(schema: str = "") -> list:
         p = []
 
         if StorageBackend.type() == StorageBackend.FILESYSTEM:
+            self.debug("List projects from filesystem")
             for i in QSAProject._qgis_projects_dir().glob("**/*.qgs"):
                 name = i.parent.name.replace(
                     QSAProject._qgis_project_dir_prefix(), ""
                 )
                 p.append(QSAProject(name))
         else:
+            self.debug("List projects from PostgreSQL database")
             service = config().qgisserver_projects_psql_service
             uri = f"postgresql:?service={service}&schema={schema}"
 
@@ -81,13 +84,16 @@ def projects(schema: str = "") -> list:
             for pname in storage.listProjects(uri):
                 p.append(QSAProject(pname, schema))
 
+        self.debug(f"{len(p)} projects found")
+
         return p
 
     @property
     def styles(self) -> list[str]:
         s = []
         for qml in self._qgis_project_dir.glob("**/*.qml"):
             s.append(qml.stem)
+        self.debug(f"{len(s)} styles found")
         return s
 
     @property
@@ -102,6 +108,7 @@ def layers(self) -> list:
         p = self.project
         for layer in p.mapLayers().values():
             layers.append(layer.name())
+        self.debug(f"{len(layers)} layers found")
         return layers
 
     @property
@@ -196,6 +203,7 @@ def layer_update_style(
         layer = project.mapLayersByName(layer_name)[0]
 
         if style_name not in layer.styleManager().styles():
+            self.debug(f"Add new style {style_name} in style manager")
             l = layer.clone()
             l.loadNamedStyle(style_path.as_posix())  # set "default" style
 
@@ -204,18 +212,22 @@ def layer_update_style(
             )
 
         if current:
+            self.debug(f"Set default style {style_name}")
             layer.styleManager().setCurrentStyle(style_name)
 
             # refresh min/max for the current layer if necessary
             # (because the style is built on an empty geotiff)
             if layer.type() == QgsMapLayer.RasterLayer:
+                self.debug("Refresh symbology renderer min/max")
                 renderer = RasterSymbologyRenderer(layer.renderer().type())
                 renderer.refresh_min_max(layer)
 
             if self._mapproxy_enabled:
+                self.debug("Clear MapProxy cache")
                 mp = QSAMapProxy(self.name)
                 mp.clear_cache(layer_name)
 
+        self.debug("Write project")
         project.write()
 
         return True, ""
@@ -278,10 +290,12 @@ def create(self, author: str) -> (bool, str):
         crs.createFromString("EPSG:3857")  # default to webmercator
         project.setCrs(crs)
 
+        self.debug("Write QGIS project")
         rc = project.write(self._qgis_project_uri)
 
         # create mapproxy config file
         if self._mapproxy_enabled:
+            self.debug("Write MapProxy configuration file")
             mp = QSAMapProxy(self.name)
             mp.create()
 
@@ -316,20 +330,29 @@ def add_layer(
         if t is None:
             return False, "Invalid layer type"
 
+        if name in self.layers:
+            return False, f"A layer {name} already exists"
+
         lyr = None
         if t == Qgis.LayerType.Vector:
+            self.debug("Init vector layer")
             provider = "ogr"
             if "table=" in datasource:
                 provider = "postgres"
             lyr = QgsVectorLayer(datasource, name, provider)
         elif t == Qgis.LayerType.Raster:
+            self.debug("Init raster layer")
             lyr = QgsRasterLayer(datasource, name, "gdal")
 
             ovr = RasterOverview(lyr)
-            if overview and not ovr.is_valid():
-                rc, err = ovr.build()
-                if not rc:
-                    return False, err
+            if overview:
+                if not ovr.is_valid():
+                    self.debug("Build overviews")
+                    rc, err = ovr.build()
+                    if not rc:
+                        return False, err
+                else:
+                    self.debug("Overviews already exist")
         else:
             return False, "Invalid layer type"
 
@@ -344,26 +367,32 @@ def add_layer(
         # create project
         project = QgsProject()
         project.read(self._qgis_project_uri)
-
         project.addMapLayer(lyr)
+
+        self.debug("Write QGIS project")
         project.write()
 
         # set default style
         if t == Qgis.LayerType.Vector:
+            self.debug("Set default style")
             geometry = lyr.geometryType().name.lower()
             default_style = self.style_default(geometry)
 
             self.layer_update_style(name, default_style, True)
 
         # add layer in mapproxy config file
-        bbox = list(
-            map(
-                float,
-                lyr.extent().asWktCoordinates().replace(",", "").split(" "),
+        if self._mapproxy_enabled:
+            self.debug("Update MapProxy configuration file")
+            bbox = list(
+                map(
+                    float,
+                    lyr.extent()
+                    .asWktCoordinates()
+                    .replace(",", "")
+                    .split(" "),
+                )
             )
-        )
 
-        if self._mapproxy_enabled:
             epsg_code = int(lyr.crs().authid().split(":")[1])
 
             mp = QSAMapProxy(self.name)
@@ -590,6 +619,14 @@ def remove_style(self, name: str) -> bool:
 
         return True, ""
 
+    def debug(self, msg) -> None:
+        caller = f"{self.__class__.__name__}.{sys._getframe().f_back.f_code.co_name}"
+        if StorageBackend.type() == StorageBackend.FILESYSTEM:
+            msg = f"[{caller}][{self.name}] {msg}"
+        else:
+            msg = f"[{caller}][{self.schema}:{self.name}] {msg}"
+        logger().debug(msg)
+
     @staticmethod
     def _qgis_projects_dir() -> Path:
         return Path(config().qgisserver_projects_dir)

qsa-api/qsa_api/raster/overview.py

@@ -1,13 +1,53 @@
 # coding: utf8
 
+import os
+import sys
 import boto3
+import logging
+import threading
 from pathlib import Path
+from botocore.exceptions import ClientError
 
 from qgis.core import QgsRasterLayer, Qgis
 
+from ..utils import logger
 from ..config import QSAConfig
 
 
+# see boto3 doc
+class ProgressPercentage:
+
+    def __init__(self, filename):
+        self._filename = filename
+        self._size = float(os.path.getsize(filename))
+        self._seen_so_far = 0
+        self._lock = threading.Lock()
+        self._last = 0
+
+    def __call__(self, bytes_amount):
+        with self._lock:
+            self._seen_so_far += bytes_amount
+            percentage = (self._seen_so_far / self._size) * 100
+
+            if percentage < self._last + 10:
+                return
+
+            self._last = percentage
+
+            if QSAConfig().loglevel == logging.DEBUG:
+                print(
+                    "\r%s  %s / %s  (%.2f%%)"
+                    % (
+                        self._filename,
+                        self._seen_so_far,
+                        self._size,
+                        percentage,
+                    ),
+                    file=sys.stderr,
+                )
+            sys.stdout.flush()
+
+
 class RasterOverview:
     def __init__(self, layer: QgsRasterLayer) -> None:
         self.layer = layer
@@ -23,6 +63,7 @@ def build(self) -> (bool, str):
             return False, "Building overviews is only supported for S3 rasters"
 
         # config overviews
+        self.debug("Build external overviews")
         levels = self.layer.dataProvider().buildPyramidList()
         for idx, level in enumerate(levels):
             levels[idx].setBuild(True)
@@ -42,14 +83,29 @@ def build(self) -> (bool, str):
             return False, f"Cannot find OVR file in GDAL_PAM_PROXY_DIR"
 
         # upload : not robust enough :/
+        size = float(os.path.getsize(ovrpath.as_posix()) >> 20)
         bucket = ds.split("/")[2]
         subdir = Path(ds.split(f"/vsis3/{bucket}/")[1]).parent
-        s3 = boto3.resource("s3")
-        s3.Bucket(bucket).upload_file(
-            ovrpath.as_posix(), (subdir / ovrfile).as_posix()
-        )
+        dest = (subdir / ovrfile).as_posix()
+        self.debug(f"Upload {dest} ({size}MB) to S3 bucket")
+
+        try:
+            s3 = boto3.resource("s3")
+            s3.Bucket(bucket).upload_file(
+                ovrpath.as_posix(),
+                dest,
+                Callback=ProgressPercentage(ovrpath.as_posix()),
+            )
+        except ClientError as e:
+            return False, "Upload to S3 bucket failed"
 
         # clean
+        self.debug("Remove ovr file in GDAL PAM directory")
         ovrpath.unlink()
 
         return True, ""
+
+    def debug(self, msg) -> None:
+        caller = f"{self.__class__.__name__}.{sys._getframe().f_back.f_code.co_name}"
+        msg = f"[{caller}] {msg}"
+        logger().debug(msg)

qsa-api/qsa_api/utils.py

@@ -8,6 +8,10 @@ def config():
     return current_app.config["CONFIG"]
 
 
+def logger():
+    return current_app.logger
+
+
 class StorageBackend(Enum):
     FILESYSTEM = 0
     POSTGRESQL = 1