From ce6cedac4ac161685c4c2efd8c47a6d363a461f1 Mon Sep 17 00:00:00 2001
From: Lubomir Bucek <lubomir.bucek@eox.at>
Date: Mon, 28 Sep 2020 10:15:17 +0200
Subject: [PATCH] logging updates
---
preprocessor/preprocessor/preprocess.py | 42 ++++++---------------
preprocessor/preprocessor/steps/output.py | 2 +
preprocessor/preprocessor/transfer/swift.py | 3 +-
preprocessor/preprocessor/util.py | 20 ++++++++++
4 files changed, 35 insertions(+), 32 deletions(-)
diff --git a/preprocessor/preprocessor/preprocess.py b/preprocessor/preprocessor/preprocess.py
index 2b35432e..355505e7 100644
--- a/preprocessor/preprocessor/preprocess.py
+++ b/preprocessor/preprocessor/preprocess.py
@@ -6,7 +6,6 @@ import logging
import shutil
from typing import List
from pprint import pformat
-from time import time
from urllib.parse import urlparse
from .transfer import get_downloader, get_uploader
@@ -16,7 +15,7 @@ from .steps import (
georeference_step, extract_subdataset_step, calc_step, stack_bands_step, output_step
)
from .steps.browse_report import browse_georeference
-from .util import workdir
+from .util import workdir, Timer
logging.basicConfig()
@@ -72,25 +71,6 @@ def flatten(l):
return [item for sublist in l for item in sublist]
-class Timer:
- """ Helper timer class to allow logging of timing values
- """
- def __init__(self):
- self.start = None
- self.end = None
-
- def __enter__(self):
- self.start = time()
- return self
-
- def __exit__(self, *args, **kwargs):
- self.end = time()
-
- @property
- def elapsed(self):
- return (self.end if self.end is not None else time()) - self.start
-
-
# -----------------------------------------------------------------------------
@@ -117,7 +97,7 @@ def preprocess_internal(preprocess_config, previous_step='unpack'):
preprocessor(previous_step, step, **step_config)
logger.info(
- 'Finished preprocessing step %s after %f seconds.'
+ 'Finished preprocessing step %s after %.3f seconds.'
% (step, step_timer.elapsed)
)
force_refresh = True
@@ -158,7 +138,7 @@ def preprocess_file(config: dict, file_path: os.PathLike, use_dir: os.PathLike=N
source_archive_path = downloader.download(file_path, 'download')
logger.info(
- 'Downloaded file %s in %f seconds'
+ 'Downloaded file %s in %.3f seconds'
% (file_path, download_timer.elapsed)
)
@@ -171,7 +151,7 @@ def preprocess_file(config: dict, file_path: os.PathLike, use_dir: os.PathLike=N
# open the XML to retrieve the product type and level
product_type, product_level = extract_product_type_and_level(metadata_files, config)
- logger.info('Detected %s/%s' % (product_type, product_level))
+ logger.info('Detected product_type/level_type %s/%s' % (product_type, product_level))
# get a concrete configuration for the type, filled with the defaults
default_config = dict(config['preprocessing'].get('defaults', {}))
@@ -208,7 +188,7 @@ def preprocess_file(config: dict, file_path: os.PathLike, use_dir: os.PathLike=N
])
logger.info(
- 'Unpacked files: %s in %f seconds'
+ 'Unpacked files: %s in %.3f seconds'
% (', '.join(metadata_files + data_files), unpack_timer.elapsed)
)
else:
@@ -244,12 +224,12 @@ def preprocess_file(config: dict, file_path: os.PathLike, use_dir: os.PathLike=N
uploader.upload(upload_filenames, file_path)
logger.info(
- 'Finished uploading after %f seconds.'
+ 'Finished uploading after %.3f seconds.'
% (upload_timer.elapsed)
)
logger.info(
- 'Finished preprocessing of %s after %f seconds.'
+ 'Finished preprocessing of %s after %.3f seconds.'
% (file_path, preprocess_timer.elapsed)
)
@@ -278,7 +258,7 @@ def preprocess_browse(config: dict, browse_type: str, browse_report: dict, brows
source_filename_path = downloader.download(filename, 'download')
logger.info(
- 'Downloaded file %s in %f seconds'
+ 'Downloaded file %s in %.3f seconds'
% (filename, download_timer.elapsed)
)
@@ -300,7 +280,7 @@ def preprocess_browse(config: dict, browse_type: str, browse_report: dict, brows
# fetch the product type from the browse_type
product_type = config.get('browse_type_mapping', {}).get(browse_type, browse_type)
- logger.info('Detected %s' % (product_type))
+ logger.info('Detected product_type %s' % (product_type))
# get a concrete configuration for the type, filled with the defaults
default_config = dict(config['preprocessing'].get('defaults', {}))
@@ -336,12 +316,12 @@ def preprocess_browse(config: dict, browse_type: str, browse_report: dict, brows
uploader.upload(upload_filenames, file_path)
logger.info(
- 'Finished uploading after %f seconds.'
+ 'Finished uploading after %.3f seconds.'
% (upload_timer.elapsed)
)
logger.info(
- 'Finished preprocessing of browse "%s" after %f seconds.'
+ 'Finished preprocessing of browse "%s" after %.3f seconds.'
% (filename, preprocess_timer.elapsed)
)
diff --git a/preprocessor/preprocessor/steps/output.py b/preprocessor/preprocessor/steps/output.py
index 882e428f..d90c5343 100644
--- a/preprocessor/preprocessor/steps/output.py
+++ b/preprocessor/preprocessor/steps/output.py
@@ -21,6 +21,7 @@ def output_step(source_dir: os.PathLike, target_dir: os.PathLike, options: dict=
warped_files = []
for filename in [path for path in glob(join(source_dir, '**'), recursive=True) if not os.path.isdir(path)]:
target_filename = join(target_dir, replace_ext(basename(filename), extension))
+ logger.debug('Warping file %s' % filename)
gdal.Warp(target_filename, filename, options=gdal.WarpOptions(
**options
))
@@ -28,6 +29,7 @@ def output_step(source_dir: os.PathLike, target_dir: os.PathLike, options: dict=
if len(warped_files) > 1:
tmp_filename = join(target_dir, '%s.%s' % (uuid4().hex, extension))
+ logger.debug('Warping files %s' % warped_files)
gdal.Warp(tmp_filename, warped_files, options=gdal.WarpOptions(
**options
))
diff --git a/preprocessor/preprocessor/transfer/swift.py b/preprocessor/preprocessor/transfer/swift.py
index ae0ac7a6..7ecd853c 100644
--- a/preprocessor/preprocessor/transfer/swift.py
+++ b/preprocessor/preprocessor/transfer/swift.py
@@ -6,7 +6,8 @@ import logging
from swiftclient.multithreading import OutputManager
from swiftclient.service import SwiftError, SwiftService, SwiftUploadObject
-
+logging.getLogger("requests").setLevel(logging.WARNING)
+logging.getLogger("swiftclient").setLevel(logging.WARNING)
logger = logging.getLogger(__name__)
class Base:
diff --git a/preprocessor/preprocessor/util.py b/preprocessor/preprocessor/util.py
index 11bdd5db..249176c5 100644
--- a/preprocessor/preprocessor/util.py
+++ b/preprocessor/preprocessor/util.py
@@ -2,6 +2,7 @@ import os
from os.path import splitext
from contextlib import contextmanager
from tempfile import TemporaryDirectory, mkdtemp
+from time import time
try:
from osgeo import gdal
@@ -46,3 +47,22 @@ def pairwise(col):
yield (next(iterator), next(iterator))
except StopIteration:
break
+
+
+class Timer:
+ """ Helper timer class to allow logging of timing values
+ """
+ def __init__(self):
+ self.start = None
+ self.end = None
+
+ def __enter__(self):
+ self.start = time()
+ return self
+
+ def __exit__(self, *args, **kwargs):
+ self.end = time()
+
+ @property
+ def elapsed(self):
+ return (self.end if self.end is not None else time()) - self.start
--
GitLab