implement logging (#66)

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__))
 

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

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
 

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')

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 = '<!-- PyWPS %s -->\n' % __version__
     xml = lxml.etree.tostring(doc, pretty_print=True)
     response = Response(pywps_version_comment.encode('utf8') + xml,

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

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()