diff --git a/pywps/__init__.py b/pywps/__init__.py index ec63c3020..99616c8a9 100644 --- a/pywps/__init__.py +++ b/pywps/__init__.py @@ -1,8 +1,5 @@ -""" -This package contains classes necessary for input parsing OGC WPS requests, -working with list of processes, executing them and redirecting OGC WPS -responses back to client. -""" +############################################################################## +# # Author: Alex Morega & Calin Ciociu # # License: @@ -27,12 +24,19 @@ # LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING # FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS # IN THE SOFTWARE. +# +############################################################################## +import logging import os + from lxml.builder import ElementMaker __version__ = '4.0.0-alpha2' +LOGGER = logging.getLogger(__name__) + +LOGGER.debug('setting core variables') PYWPS_INSTALL_DIR = os.path.dirname(os.path.abspath(__file__)) diff --git a/pywps/_compat.py b/pywps/_compat.py index 6bb832bdb..5d120a3a2 100644 --- a/pywps/_compat.py +++ b/pywps/_compat.py @@ -1,5 +1,5 @@ -""" Compatibility support for Python 2 and 3 """ - +############################################################################### +# # Author: Alex Morega (?) # # License: @@ -24,12 +24,17 @@ # LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING # FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS # IN THE SOFTWARE. +# +############################################################################### +import logging import sys +LOGGER = logging.getLogger(__name__) PY2 = sys.version_info[0] == 2 if PY2: + LOGGER.debug('Python 2.x') text_type = unicode from StringIO import StringIO from flufl.enum import Enum @@ -38,6 +43,7 @@ from urllib2 import urlopen else: + LOGGER.debug('Python 3.x') text_type = str from io import StringIO from enum import Enum diff --git a/pywps/app/Process.py b/pywps/app/Process.py index e7b892503..c42697285 100644 --- a/pywps/app/Process.py +++ b/pywps/app/Process.py @@ -1,11 +1,39 @@ +############################################################################### +# +# Copyright (C) 2014-2016 PyWPS Development Team, represented by +# PyWPS Project Steering Committee +# +# Permission is hereby granted, free of charge, to any person obtaining a copy +# of this software and associated documentation files (the "Software"), to +# deal in the Software without restriction, including without limitation the +# rights to use, copy, modify, merge, publish, distribute, sublicense, and/or +# sell copies of the Software, and to permit persons to whom the Software is +# furnished to do so, subject to the following conditions: +# +# The above copyright notice and this permission notice shall be included in +# all copies or substantial portions of the Software. +# +# THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +# IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +# FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +# AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +# LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING +# FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS +# IN THE SOFTWARE. +# +############################################################################### + +import logging import os import sys +import traceback + from pywps import WPS, OWS, E from pywps.app.WPSResponse import WPSResponse -from pywps.exceptions import StorageNotSupported, OperationNotSupported import pywps.configuration as config -import traceback +from pywps.exceptions import StorageNotSupported, OperationNotSupported +LOGGER = logging.getLogger(__name__) class Process(object): """ @@ -107,7 +135,7 @@ def execute(self, wps_request, uuid): async = False wps_response = WPSResponse(self, wps_request, self.uuid) - # check if status storage and updating are supported by this process + LOGGER.debug('Check if status storage and updating are supported by this process') if wps_request.store_execute == 'true': if self.store_supported != 'true': raise StorageNotSupported('Process does not support the storing of the execute response') @@ -130,7 +158,7 @@ def execute(self, wps_request, uuid): else: wps_response.status = WPSResponse.STORE_STATUS - # check if updating of status is not required then no need to spawn a process + LOGGER.debug('Check if updating of status is not required then no need to spawn a process') if async: process = multiprocessing.Process(target=self._run_process, args=(wps_request, wps_response)) process.start() @@ -145,11 +173,11 @@ def _run_process(self, wps_request, wps_response): # if status not yet set to 100% then do it after execution was successful if wps_response.status_percentage != 100: - # update the process status to 100% if everything went correctly + LOGGER.debug('Updating process status to 100% if everything went correctly') wps_response.update_status('PyWPS Process finished', 100) except Exception as e: traceback.print_exc() - # retrieve the file and line number where the exception occurred + LOGGER.debug('Retrieving file and line number where exception occurred') exc_type, exc_obj, exc_tb = sys.exc_info() found = False while not found: @@ -168,7 +196,9 @@ def _run_process(self, wps_request, wps_response): method_name = exc_tb.tb_frame.f_code.co_name # update the process status to display process failed - wps_response.update_status('Process error: %s.%s Line %i %s' % (fname, method_name, exc_tb.tb_lineno, e), -1) + msg = 'Process error: %s.%s Line %i %s' % (fname, method_name, exc_tb.tb_lineno, e) + LOGGER.error(msg) + wps_response.update_status(msg, -1) return wps_response diff --git a/pywps/app/Service.py b/pywps/app/Service.py index 094e7f83a..eb300ba2a 100644 --- a/pywps/app/Service.py +++ b/pywps/app/Service.py @@ -1,3 +1,4 @@ +import logging import tempfile from werkzeug.exceptions import BadRequest, HTTPException from werkzeug.wrappers import Request, Response @@ -18,6 +19,7 @@ import os import uuid +LOGGER = logging.getLogger(__name__) class Service(object): @@ -31,6 +33,15 @@ class Service(object): def __init__(self, processes=[]): self.processes = {p.identifier: p for p in processes} + if config.get_config_value('server', 'logfile') and config.get_config_value('server', 'loglevel'): + LOGGER.setLevel(getattr(logging, config.get_config_value('server', 'loglevel'))) + msg_fmt = '%(asctime)s] [%(levelname)s] file=%(pathname)s line=%(lineno)s module=%(module)s function=%(funcName)s %(message)s' + fh = logging.FileHandler(config.get_config_value('server', 'logfile')) + fh.setFormatter(logging.Formatter(msg_fmt)) + LOGGER.addHandler(fh) + else: # NullHandler + LOGGER.addHandler(logging.NullHandler()) + def get_capabilities(self): process_elements = [p.capabilities_xml() for p in self.processes.values()] @@ -293,16 +304,17 @@ def execute(self, identifier, wps_request, uuid): def _parse_and_execute(self, process, wps_request, uuid): """Parse and execute request """ - # check if datainputs is required and has been passed + LOGGER.debug('Checking if datainputs is required and has been passed') if process.inputs: if wps_request.inputs is None: raise MissingParameterValue('', 'datainputs') - # check if all mandatory inputs have been passed + LOGGER.debug('Checking if all mandatory inputs have been passed') data_inputs = {} for inpt in process.inputs: if inpt.identifier not in wps_request.inputs: if inpt.min_occurs > 0: + LOGGER.error('Missing parameter value: %s', inpt.identifier) raise MissingParameterValue( inpt.identifier, inpt.identifier) else: @@ -385,6 +397,7 @@ def href_handler(complexinput, datain): # if the response did not return a 'Content-Length' header then # calculate the size if data_size == 0: + LOGGER.debug('no Content-Length, calculating size') data_size = _get_datasize(reference_file_data) # check if input file size was not exceeded @@ -398,7 +411,6 @@ def href_handler(complexinput, datain): try: with open(tmp_file, 'w') as f: f.write(reference_file_data) - f.close() except Exception as e: raise NoApplicableCode(e) @@ -505,10 +517,12 @@ def __call__(self, http_request): environ_cfg = http_request.environ.get('PYWPS_CFG') if not 'PYWPS_CFG' in os.environ and environ_cfg: + LOGGER.debug('Setting PYWPS_CFG to %s', environ_cfg) os.environ['PYWPS_CFG'] = environ_cfg try: wps_request = WPSRequest(http_request) + LOGGER.info('Request: %s', wps_request.operation) if wps_request.operation in ['getcapabilities', 'describeprocess', 'execute']: @@ -553,6 +567,7 @@ def _openurl(inpt): reference_file = None href = inpt.get('href') + LOGGER.debug('Fetching URL %s', href) if inpt.get('method') == 'POST': if inpt.has_key('body'): data = inpt.get('body') diff --git a/pywps/app/basic.py b/pywps/app/basic.py index 756309df7..07ebaede0 100644 --- a/pywps/app/basic.py +++ b/pywps/app/basic.py @@ -1,13 +1,18 @@ +import logging import lxml from werkzeug.wrappers import Response from pywps import __version__, OWS, NAMESPACES, OGCUNIT +LOGGER = logging.getLogger(__name__) def xpath_ns(el, path): return el.xpath(path, namespaces=NAMESPACES) def xml_response(doc): + """XML response serializer""" + + LOGGER.debug('Serializing XML response') pywps_version_comment = '\n' % __version__ xml = lxml.etree.tostring(doc, pretty_print=True) response = Response(pywps_version_comment.encode('utf8') + xml, diff --git a/pywps/configuration.py b/pywps/configuration.py index b9a22fe18..898dc7956 100755 --- a/pywps/configuration.py +++ b/pywps/configuration.py @@ -26,6 +26,7 @@ # FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS # IN THE SOFTWARE. +import logging import sys import os import tempfile @@ -39,6 +40,7 @@ config = None +LOGGER = logging.getLogger(__name__) def get_config_value(section, option): @@ -77,12 +79,13 @@ def load_configuration(cfgfiles=None): global config + LOGGER.info('loading configuration') if PY2: config = ConfigParser.SafeConfigParser() else: config = configparser.ConfigParser() - # Set default values + LOGGER.debug('setting default values') config.add_section('server') config.set('server', 'encoding', 'utf-8') config.set('server', 'language', 'en-US') @@ -130,9 +133,9 @@ def load_configuration(cfgfiles=None): loaded_files = config.read(cfgfiles) if loaded_files: - print('Configuration file(s) {} loaded'.format(loaded_files)) + LOGGER.info('Configuration file(s) %s loaded', loaded_files) else: - print('No configuration files loaded. Using default values.') + LOGGER.info('No configuration files loaded. Using default values') def _get_default_config_files_location(): """Get the locations of the standard configuration files. These are @@ -148,20 +151,25 @@ def _get_default_config_files_location(): :rtype: list of strings """ - # configuration file as environment variable - if os.getenv("PYWPS_CFG"): + is_win32 = sys.platform == 'win32' + if is_win32: + LOGGER.debug('Windows based environment') + else: + LOGGER.debug('UNIX based environment') + if os.getenv("PYWPS_CFG"): + LOGGER.debug('using PYWPS_CFG environment variable') # Windows or Unix - if sys.platform == 'win32': + if is_win32: PYWPS_INSTALL_DIR = os.path.abspath(os.path.join(os.getcwd(), os.path.dirname(sys.argv[0]))) cfgfiles = (os.getenv("PYWPS_CFG")) else: cfgfiles = (os.getenv("PYWPS_CFG")) - # try to eastimate the default location else: + LOGGER.debug('trying to estimate the default location') # Windows or Unix - if sys.platform == 'win32': + if is_win32: PYWPS_INSTALL_DIR = os.path.abspath(os.path.join(os.getcwd(), os.path.dirname(sys.argv[0]))) cfgfiles = (os.path.join(PYWPS_INSTALL_DIR, "pywps", "etc", "pywps.cfg")) else: @@ -195,4 +203,5 @@ def get_size_mb(mbsize): newsize /= 1024 else: newsize *= 1 + LOGGER.debug('Calculated real size of %s is %s', mbsize, newsize) return newsize diff --git a/pywps/dblog.py b/pywps/dblog.py index 96a2b831c..898052014 100644 --- a/pywps/dblog.py +++ b/pywps/dblog.py @@ -2,11 +2,13 @@ Implementation of logging for PyWPS-4 """ +import logging from pywps import configuration from pywps.exceptions import NoApplicableCode import sqlite3 import datetime +LOGGER = logging.getLogger(__name__) _CONNECTION = None def log_request(uuid, request): @@ -27,6 +29,7 @@ def log_request(uuid, request): time_start=datetime.datetime.now().isoformat(), identifier=_get_identifier(request) ) + LOGGER.debug(insert) cur = conn.cursor() cur.execute(insert) conn.commit() @@ -63,6 +66,7 @@ def update_response(uuid, response, close=False): status=status, uuid=uuid ) + LOGGER.debug(update) cur = conn.cursor() cur.execute(update) conn.commit() @@ -87,6 +91,7 @@ def get_connection(): """Get Connection for database """ + LOGGER.debug('Initializing database connection') global _CONNECTION if _CONNECTION: @@ -145,8 +150,10 @@ def check_db_table(connection): """) table = cursor.fetchone() if table: + LOGGER.debug('pywps_requests table exists') return True else: + LOGGER.debug('pywps_requests table does not exist') return False @@ -179,6 +186,8 @@ def check_db_columns(connection): return False def close_connection(): + """close connection""" + LOGGER.debug('Closing DB connection') global _CONNECTION if _CONNECTION: _CONNECTION.close() diff --git a/pywps/exceptions.py b/pywps/exceptions.py index 2fb671656..1dbcbd9b4 100644 --- a/pywps/exceptions.py +++ b/pywps/exceptions.py @@ -39,6 +39,8 @@ from pywps import __version__ +LOGGER = logging.getLogger(__name__) + class NoApplicableCode(HTTPException): """No applicable code exception implementation @@ -54,7 +56,8 @@ def __init__(self, description, locator="", code=400): self.code = code self.description = description self.locator = locator - logging.exception(description) + msg = 'Exception: code: %s, locator: %s, description: %s' % (self.code, self.description, self.locator) + LOGGER.exception(msg) HTTPException.__init__(self) diff --git a/pywps/inout/storage.py b/pywps/inout/storage.py index 279f5f53a..7e3ceac49 100644 --- a/pywps/inout/storage.py +++ b/pywps/inout/storage.py @@ -1,9 +1,11 @@ from abc import ABCMeta, abstractmethod, abstractproperty +import logging import os from pywps._compat import urljoin from pywps.exceptions import NotEnoughStorage, NoApplicableCode from pywps import configuration as config +LOGGER = logging.getLogger(__name__) class STORE_TYPE: PATH = 0 @@ -98,11 +100,14 @@ def store(self, output): output_name = tempfile.mkstemp(suffix=suffix, prefix=file_name, dir=self.target)[1] - shutil.copy2(output.file, os.path.join(self.target, output_name)) + full_output_name = os.path.join(self.target, output_name) + LOGGER.info('Storing file output to %s', full_output_name) + shutil.copy2(output.file, full_output_name) just_file_name = os.path.basename(output_name) url = urljoin(self.output_url, just_file_name) + LOGGER.info('File output URI: %s', url) return (STORE_TYPE.PATH, output_name, url) @@ -117,6 +122,9 @@ def get_free_space(folder): free_bytes = ctypes.c_ulonglong(0) ctypes.windll.kernel32.GetDiskFreeSpaceExW(ctypes.c_wchar_p(folder), None, None, ctypes.pointer(free_bytes)) - return free_bytes.value + free_space = free_bytes.value else: - return os.statvfs(folder).f_bfree + free_space = os.statvfs(folder).f_bfree + + LOGGER.debug('Free space: %s', free_space) + return free_space diff --git a/pywps/validator/__init__.py b/pywps/validator/__init__.py index cdd33163e..96d8f5427 100644 --- a/pywps/validator/__init__.py +++ b/pywps/validator/__init__.py @@ -1,5 +1,6 @@ """Validatating functions for various inputs """ +import logging from collections import namedtuple from pywps.validator.complexvalidator import validategml, validateshapefile, validategeojson, validategeotiff from pywps.validator.literalvalidator import validate_anyvalue, validate_allowed_values @@ -7,6 +8,7 @@ from pywps.validator.mode import MODE from pywps.validator.base import emptyvalidator +LOGGER = logging.getLogger(__name__) _VALIDATORS = { 'application/vnd.geo+json': validategeojson, @@ -36,6 +38,8 @@ def get_validator(identifier): """ if identifier in _VALIDATORS: + LOGGER.debug('validator: %s', _VALIDATORS[identifier]) return _VALIDATORS[identifier] else: + LOGGER.debug('empty validator') return emptyvalidator diff --git a/pywps/validator/complexvalidator.py b/pywps/validator/complexvalidator.py index 5e44c0446..dff82cffa 100644 --- a/pywps/validator/complexvalidator.py +++ b/pywps/validator/complexvalidator.py @@ -25,11 +25,15 @@ # FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS # IN THE SOFTWARE. +import logging + from pywps.validator.mode import MODE from pywps.inout.formats.lists import FORMATS import mimetypes import os +LOGGER = logging.getLogger(__name__) + def validategml(data_input, mode): """GML validation example @@ -47,6 +51,8 @@ def validategml(data_input, mode): >>> validategml(fake_input, MODE.SIMPLE) True """ + + LOGGER.info('validating GML; Mode: %s', mode) passed = False if mode >= MODE.NONE: @@ -104,6 +110,8 @@ def validategeojson(data_input, mode): >>> validategeojson(fake_input, MODE.SIMPLE) True """ + + LOGGER.info('validating GeoJSON; Mode: %s', mode) passed = False if mode >= MODE.NONE: @@ -169,6 +177,8 @@ def validateshapefile(data_input, mode): """ESRI Shapefile validation example """ + + LOGGER.info('validating Shapefile; Mode: %s', mode) passed = False if mode >= MODE.NONE: @@ -205,6 +215,8 @@ def validateshapefile(data_input, mode): def validategeotiff(data_input, mode): """GeoTIFF validation example """ + + LOGGER.info('Validating Shapefile; Mode: %s', mode) passed = False if mode >= MODE.NONE: @@ -230,12 +242,14 @@ def validategeotiff(data_input, mode): def _get_schemas_home(): """Get path to schemas directory """ - return os.path.join( + schema_dir = os.path.join( os.path.abspath( os.path.dirname(__file__) ), os.path.pardir, "schemas") + LOGGER.debug('Schemas directory: %s', schema_dir) + return schema_dir if __name__ == "__main__": diff --git a/pywps/validator/literalvalidator.py b/pywps/validator/literalvalidator.py index 1697e731d..ea1f0cfbe 100644 --- a/pywps/validator/literalvalidator.py +++ b/pywps/validator/literalvalidator.py @@ -25,9 +25,14 @@ # FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS # IN THE SOFTWARE. +import logging + from pywps.validator.mode import MODE from pywps.validator.allowed_value import ALLOWEDVALUETYPE, RANGECLOSURETYPE + +LOGGER = logging.getLogger(__name__) + def validate_anyvalue(data_input, mode): """Just placeholder, anyvalue is always valid """ @@ -45,6 +50,7 @@ def validate_allowed_values(data_input, mode): else: data = data_input.data + LOGGER.debug('validating allowed values: %s in %s', data, data_input.allowed_values) for value in data_input.allowed_values: if value.allowed_type == ALLOWEDVALUETYPE.VALUE: @@ -56,6 +62,7 @@ def validate_allowed_values(data_input, mode): if passed is True: break + LOGGER.debug('validation result: %r', passed) return passed @@ -79,6 +86,7 @@ def _validate_range(interval, data): passed = False + LOGGER.debug('validating range: %s in %r', data, interval) if interval.minval <= data <= interval.maxval: if interval.spacing: @@ -100,4 +108,5 @@ def _validate_range(interval, data): else: passed = False + LOGGER.debug('validation result: %r', passed) return passed