Added new logger to all the functions

2016-08-01 19:04:56 +02:00
parent 5d5e8d6f9a
commit ed5cf25e9c
37 changed files with 384 additions and 257 deletions
--- a/server/lib/python/cartodb_services/cartodb_services/google/geocoder.py
+++ b/server/lib/python/cartodb_services/cartodb_services/google/geocoder.py
@@ -9,11 +9,12 @@ from exceptions import MalformedResult
 class GoogleMapsGeocoder:
    """A Google Maps Geocoder wrapper for python"""

-    def __init__(self, client_id, client_secret):
+    def __init__(self, client_id, client_secret, logger):
        self.client_id = self._clean_client_id(client_id)
        self.client_secret = client_secret
        self.geocoder = googlemaps.Client(
            client_id=self.client_id, client_secret=self.client_secret)
+        self._logger = logger

    def geocode(self, searchtext, city=None, state=None,
                country=None):
--- a/server/lib/python/cartodb_services/cartodb_services/here/geocoder.py
+++ b/server/lib/python/cartodb_services/cartodb_services/here/geocoder.py
@@ -47,10 +47,11 @@ class HereMapsGeocoder:
        'strictlanguagemode'
        ] + ADDRESS_PARAMS

-    def __init__(self, app_id, app_code, maxresults=DEFAULT_MAXRESULTS,
+    def __init__(self, app_id, app_code, logger, maxresults=DEFAULT_MAXRESULTS,
                 gen=DEFAULT_GEN, host=PRODUCTION_GEOCODE_JSON_URL):
        self.app_id = app_id
        self.app_code = app_code
+        self._logger = logger
        self.maxresults = maxresults
        self.gen = gen
        self.host = host
@@ -88,9 +89,15 @@ class HereMapsGeocoder:
        if response.status_code == requests.codes.ok:
            return json.loads(response.text)
        elif response.status_code == requests.codes.bad_request:
+            self._logger.warning('Error 4xx trying to geocode street using HERE',
+                               data={"response": response.json(), "params":
+                                     params})
            return []
        else:
-            response.raise_for_status()
+            self._logger.error('Error trying to geocode street using HERE',
+                               data={"response": response.json(), "params":
+                                     params})
+            raise Exception('Error trying to geocode street using Here')

    def _extract_lng_lat_from_result(self, result):
        location = result['Location']
--- a/server/lib/python/cartodb_services/cartodb_services/here/routing.py
+++ b/server/lib/python/cartodb_services/cartodb_services/here/routing.py
@@ -25,9 +25,11 @@ class HereMapsRoutingIsoline:
        'quality'
    ]

-    def __init__(self, app_id, app_code, base_url=PRODUCTION_ROUTING_BASE_URL):
+    def __init__(self, app_id, app_code, logger,
+                 base_url=PRODUCTION_ROUTING_BASE_URL):
        self._app_id = app_id
        self._app_code = app_code
+        self._logger = logger
        self._url = "{0}{1}".format(base_url, self.ISOLINE_PATH)

    def calculate_isodistance(self, source, mode, data_range, options=[]):
@@ -54,7 +56,12 @@ class HereMapsRoutingIsoline:
        elif response.status_code == requests.codes.bad_request:
            return []
        else:
-            response.raise_for_status()
+            self._logger.error('Error trying to calculate HERE isolines',
+                               data={"response": response.json(), "source":
+                                     source, "mode": mode, "data_range":
+                                     data_range, "range_type": range_type,
+                                     "options": options})
+            raise Exception('Error trying to calculate HERE isolines')

    def __parse_options(self, options):
        return dict(option.split('=') for option in options)
--- a/server/lib/python/cartodb_services/cartodb_services/mapzen/geocoder.py
+++ b/server/lib/python/cartodb_services/cartodb_services/mapzen/geocoder.py
@@ -12,9 +12,10 @@ class MapzenGeocoder:

    BASE_URL = 'https://search.mapzen.com/v1/search'

-    def __init__(self, app_key, base_url=BASE_URL):
+    def __init__(self, app_key, logger, base_url=BASE_URL):
        self._app_key = app_key
        self._url = base_url
+        self._logger = logger

    @qps_retry
    def geocode(self, searchtext, city=None, state_province=None, country=None):
@@ -25,7 +26,7 @@ class MapzenGeocoder:
        elif response.status_code == requests.codes.bad_request:
            return []
        else:
-            response.raise_for_status()
+            raise Exception('Error trying to geocode {0} using mapzen'.format(searchtext))

    def _build_requests_parameters(self, searchtext, city=None,
                                   state_province=None, country=None):
--- a/server/lib/python/cartodb_services/cartodb_services/mapzen/matrix_client.py
+++ b/server/lib/python/cartodb_services/cartodb_services/mapzen/matrix_client.py
@@ -2,6 +2,7 @@ import requests
 import json
 from qps import qps_retry

+
 class MatrixClient:

    """
@@ -42,8 +43,14 @@ class MatrixClient:
        response = requests.get(self.ONE_TO_MANY_URL, params=request_params)

        if not requests.codes.ok:
-            self._logger.warning('Error trying to get matrix distance from mapzen', data={"response": response, "locations": locations, "costing": costing})
-
-        response.raise_for_status() # raise exception if not 200 OK
+            self._logger.error('Error trying to get matrix distance from mapzen',
+                               data={"response": response.json(), "locations":
+                                     locations, "costing": costing})
+            raise Exception('Error trying to get matrix distance from mapzen')
+        else:
+            self._logger.debug('Done get matrix distance from mapzen',
+                               data={"response": response.json(),
+                                     "locations": locations,
+                                     "costing": costing})

        return response.json()
--- a/server/lib/python/cartodb_services/cartodb_services/mapzen/routing.py
+++ b/server/lib/python/cartodb_services/cartodb_services/mapzen/routing.py
@@ -28,9 +28,10 @@ class MapzenRouting:
    METRICS_UNITS = 'kilometers'
    IMPERIAL_UNITS = 'miles'

-    def __init__(self, app_key, base_url=PRODUCTION_ROUTING_BASE_URL):
+    def __init__(self, app_key, logger, base_url=PRODUCTION_ROUTING_BASE_URL):
        self._app_key = app_key
        self._url = base_url
+        self._logger = logger

    @qps_retry
    def calculate_route_point_to_point(self, waypoints, mode,
@@ -48,7 +49,11 @@ class MapzenRouting:
        elif response.status_code == requests.codes.bad_request:
            return MapzenRoutingResponse(None, None, None)
        else:
-            response.raise_for_status()
+            self._logger.error('Error trying to calculate route using HERE',
+                               data={"response": response.json(), "waypoints":
+                                     waypoints, "mode": mode, "options":
+                                     options})
+            raise Exception('Error trying to calculate route using HERE')

    def __parse_options(self, options):
        return dict(option.split('=') for option in options)
--- a/server/lib/python/cartodb_services/cartodb_services/metrics/config.py
+++ b/server/lib/python/cartodb_services/cartodb_services/metrics/config.py
@@ -17,6 +17,8 @@ class ServiceConfig(object):
        self._db_config = ServicesDBConfig(db_conn, username, orgname)
        self._environment = self._db_config._server_environment
        self._rollbar_api_key = self._db_config._rollbar_api_key
+        self._log_file_path = self._db_config._log_file_path
+        self._min_log_level = self._db_config._min_log_level
        if redis_connection:
            self._redis_config = ServicesRedisConfig(redis_connection).build(
                username, orgname)
@@ -39,10 +41,19 @@ class ServiceConfig(object):
    def rollbar_api_key(self):
        return self._rollbar_api_key

+    @property
+    def log_file_path(self):
+        return self._log_file_path
+
+    @property
+    def min_log_level(self):
+        return self._min_log_level
+
    @property
    def environment(self):
        return self._environment

+
 class DataObservatoryConfig(ServiceConfig):

    def __init__(self, redis_connection, db_conn, username, orgname=None):
@@ -65,6 +76,7 @@ class DataObservatoryConfig(ServiceConfig):
    def connection_str(self):
        return self._connection_str

+
 class ObservatorySnapshotConfig(DataObservatoryConfig):

    SOFT_LIMIT_KEY = 'soft_obs_snapshot_limit'
@@ -88,6 +100,7 @@ class ObservatorySnapshotConfig(DataObservatoryConfig):
    def service_type(self):
        return 'obs_snapshot'

+
 class ObservatoryConfig(DataObservatoryConfig):

    SOFT_LIMIT_KEY = 'soft_obs_general_limit'
@@ -111,6 +124,7 @@ class ObservatoryConfig(DataObservatoryConfig):
    def service_type(self):
        return 'obs_general'

+
 class RoutingConfig(ServiceConfig):

    PERIOD_END_DATE = 'period_end_date'
@@ -172,6 +186,7 @@ class IsolinesRoutingConfig(ServiceConfig):
        if not self._isolines_provider:
            self._isolines_provider = self.DEFAULT_PROVIDER
        self._geocoder_provider = filtered_config[self.GEOCODER_PROVIDER_KEY].lower()
+        self._period_end_date = date_parse(filtered_config[self.PERIOD_END_DATE])
        if self._isolines_provider == self.HEREMAPS_PROVIDER:
            self._isolines_quota = float(filtered_config[self.QUOTA_KEY])
            self._heremaps_app_id = db_config.heremaps_isolines_app_id
@@ -184,7 +199,6 @@ class IsolinesRoutingConfig(ServiceConfig):
            self._mapzen_matrix_api_key = self._db_config.mapzen_matrix_api_key
            self._isolines_quota = self._db_config.mapzen_matrix_monthly_quota
            self._soft_isolines_limit = False
-        self._period_end_date = date_parse(filtered_config[self.PERIOD_END_DATE])

    @property
    def service_type(self):
@@ -473,10 +487,15 @@ class ServicesDBConfig:
        else:
            logger_conf = json.loads(logger_conf_json)
            self._geocoder_log_path = logger_conf['geocoder_log_path']
+            self._rollbar_api_key = None
+            self._min_log_level = 'warning'
+            self._log_file_path = None
+            if 'min_log_level' in logger_conf:
+                self._min_log_level = logger_conf['min_log_level']
            if 'rollbar_api_key' in logger_conf:
                self._rollbar_api_key = logger_conf['rollbar_api_key']
-            else:
-                self._rollbar_api_key = None
+            if 'log_file_path' in logger_conf:
+                self._log_file_path = logger_conf['log_file_path']

    def _get_conf(self, key):
        try:
@@ -542,6 +561,10 @@ class ServicesDBConfig:
    def rollbar_api_key(self):
        return self._rollbar_api_key

+    @property
+    def log_file_path(self):
+        return self._log_file_path
+
    @property
    def data_observatory_connection_str(self):
        return self._data_observatory_connection_str
--- a/server/lib/python/cartodb_services/cartodb_services/tools/init.py
+++ b/server/lib/python/cartodb_services/cartodb_services/tools/init.py
@@ -1,4 +1,4 @@
 from redis_tools import RedisConnection, RedisDBConfig
 from coordinates import Coordinate
 from polyline import PolyLine
-from log import Logger
+from log import Logger
--- a/server/lib/python/cartodb_services/cartodb_services/tools/log.py
+++ b/server/lib/python/cartodb_services/cartodb_services/tools/log.py
@@ -1,5 +1,7 @@
 import plpy
 import rollbar
+import logging
+import traceback
 import sys
 # Monkey path because plpython sys module doesn't have argv and rollbar
 # package use it
@@ -8,28 +10,51 @@ sys.__dict__['argv'] = []

 class Logger:

+    LEVELS = {'debug': 1, 'info': 2, 'warning': 3, 'error': 4}
+
    def __init__(self, config):
        self._config = config
+        self._min_level = self.LEVELS[self._config.min_log_level]
        # We need to set the handler blocking (synchronous) because
        # spawn a thread from plpython interpreter don't work
-        rollbar.init(self._config.rollbar_api_key,
-                     self._config.environment, handler='blocking')
+        if self._rollbar_activated():
+            rollbar.init(self._config.rollbar_api_key,
+                        self._config.environment, handler='blocking')
+        if self._log_file_activated():
+            self._setup_log_file_config(self._config.log_file_path)

    def debug(self, text, exception=None, data={}):
+        if not self._check_min_level('debug'):
+            return
        self._send_to_rollbar('debug', text, exception, data)
+        self._send_to_log_file('debug', text, exception, data)
        plpy.debug(text)

    def info(self, text, exception=None, data={}):
+        if not self._check_min_level('info'):
+            return
        self._send_to_rollbar('info', text, exception, data)
+        self._send_to_log_file('info', text, exception, data)
        plpy.info(text)

    def warning(self, text, exception=None, data={}):
+        if not self._check_min_level('warning'):
+            return
        self._send_to_rollbar('warning', text, exception, data)
+        self._send_to_log_file('warning', text, exception, data)
        plpy.warning(text)

    def error(self, text, exception=None, data={}):
+        if not self._check_min_level('error'):
+            return
        self._send_to_rollbar('error', text, exception, data)
-        plpy.error(text)
+        self._send_to_log_file('error', text, exception, data)
+        # Plpy.error and fatal raises exceptions and we only want to log an
+        # error, exceptions should be raise explicitly
+        plpy.warning(text)
+
+    def _check_min_level(self, level):
+        return True if self.LEVELS[level] >= self._min_level else False

    def _send_to_rollbar(self, level, text, exception, data):
        if self._rollbar_activated():
@@ -43,5 +68,41 @@ class Logger:
                plpy.warning('Error sending message/exception to rollbar: {0}'.
                             format(e))

+    def _send_to_log_file(self, level, text, exception, data):
+        extra_data = self._parse_log_extra_data(exception, data)
+        if level == 'debug':
+            logging.debug(text, extra=extra_data)
+        elif level == 'info':
+            logging.info(text, extra=extra_data)
+        elif level == 'warning':
+            logging.warning(text, extra=extra_data)
+        elif level == 'error':
+            logging.error(text, extra=extra_data)
+
+    def _parse_log_extra_data(self, exception, data):
+        if exception:
+            type_, value_, traceback_ = exception
+            exception_traceback = traceback.format_tb(traceback_)
+            extra_data = {"exception_type": type_, "exception_message": value_,
+                          "exception_traceback": exception_traceback,
+                          "log_data": data}
+        else:
+            extra_data = {"exception_type": '', "exception_message": '',
+                          "exception_traceback": ''}
+
+        if data:
+            extra_data['data'] = data
+        else:
+            extra_data['data'] = ''
+
+        return extra_data
+
+    def _setup_log_file_config(self, log_file_path):
+        format_str = "%(asctime)s %(name)-12s %(levelname)-8s %(message)s %(data)s %(exception_type)s %(exception_message)s %(exception_traceback)s"
+        logging.basicConfig(filename=log_file_path, format=format_str, level=self._config.min_log_level.upper())
+
    def _rollbar_activated(self):
        return True if self._config.rollbar_api_key else False
+
+    def _log_file_activated(self):
+        return True if self._config.log_file_path else False
--- a/server/lib/python/cartodb_services/test/test_googlegeocoder.py
+++ b/server/lib/python/cartodb_services/test/test_googlegeocoder.py
@@ -3,6 +3,7 @@

 import unittest
 import requests_mock
+from mock import Mock

 from cartodb_services.google import GoogleMapsGeocoder
 from cartodb_services.google.exceptions import BadGeocodingParams
@@ -89,8 +90,9 @@ class GoogleGeocoderTestCase(unittest.TestCase):
    MALFORMED_RESPONSE = """{"manolo": "escobar"}"""

    def setUp(self):
+        logger = Mock()
        self.geocoder = GoogleMapsGeocoder('dummy_client_id',
-                                 'MgxyOFxjZXIyOGO52jJlMzEzY1Oqy4hsO49E')
+                                 'MgxyOFxjZXIyOGO52jJlMzEzY1Oqy4hsO49E', logger)

    def test_geocode_address_with_valid_params(self, req_mock):
        req_mock.register_uri('GET', self.GOOGLE_MAPS_GEOCODER_URL,
--- a/server/lib/python/cartodb_services/test/test_helper.py
+++ b/server/lib/python/cartodb_services/test/test_helper.py
@@ -1,5 +1,7 @@
 from datetime import datetime, date
 from mock import Mock
+import sys
+sys.modules['plpy'] = Mock()


 def build_redis_user_config(redis_conn, username, quota=100, soft_limit=False,
@@ -72,3 +74,5 @@ def _plpy_execute_side_effect(*args, **kwargs):
        return [{'conf': '{"geocoder_log_path": "/dev/null"}'}]
    elif args[0] == "SELECT cartodb.CDB_Conf_GetConf('data_observatory_conf') as conf":
        return [{'conf': '{"connection": {"whitelist": ["ethervoid"], "production": "host=localhost port=5432 dbname=dataservices_db user=geocoder_api", "staging": "host=localhost port=5432 dbname=dataservices_db user=geocoder_api"}}'}]
+    elif args[0] == "SELECT cartodb.CDB_Conf_GetConf('server_conf') as conf":
+        return [{'conf': '{"environment": "testing"}'}]
--- a/server/lib/python/cartodb_services/test/test_heremapsgeocoder.py
+++ b/server/lib/python/cartodb_services/test/test_heremapsgeocoder.py
@@ -3,6 +3,7 @@

 import unittest
 import requests_mock
+from mock import Mock

 from cartodb_services.here import HereMapsGeocoder
 from cartodb_services.here.exceptions import BadGeocodingParams
@@ -102,7 +103,8 @@ class HereMapsGeocoderTestCase(unittest.TestCase):
    MALFORMED_RESPONSE = """{"manolo": "escobar"}"""

    def setUp(self):
-        self.geocoder = HereMapsGeocoder(None, None)
+        logger = Mock()
+        self.geocoder = HereMapsGeocoder(None, None, logger)

    def test_geocode_address_with_valid_params(self, req_mock):
        req_mock.register_uri('GET', HereMapsGeocoder.PRODUCTION_GEOCODE_JSON_URL,
--- a/server/lib/python/cartodb_services/test/test_heremapsrouting.py
+++ b/server/lib/python/cartodb_services/test/test_heremapsrouting.py
@@ -3,6 +3,7 @@

 import unittest
 import requests_mock
+from mock import Mock
 from urlparse import urlparse, parse_qs

 from cartodb_services.here import HereMapsRoutingIsoline
@@ -127,7 +128,8 @@ class HereMapsRoutingIsolineTestCase(unittest.TestCase):
    MALFORMED_RESPONSE = """{"manolo": "escobar"}"""

    def setUp(self):
-        self.routing = HereMapsRoutingIsoline(None, None)
+        logger = Mock()
+        self.routing = HereMapsRoutingIsoline(None, None, logger)
        self.isoline_url = "{0}{1}".format(HereMapsRoutingIsoline.PRODUCTION_ROUTING_BASE_URL,
                                     HereMapsRoutingIsoline.ISOLINE_PATH)

--- a/server/lib/python/cartodb_services/test/test_mapzengeocoder.py
+++ b/server/lib/python/cartodb_services/test/test_mapzengeocoder.py
@@ -1,8 +1,9 @@
 #!/usr/local/bin/python
 # -*- coding: utf-8 -*-
-
+import mock
 import unittest
 import requests_mock
+from mock import Mock

 from cartodb_services.mapzen import MapzenGeocoder
 from cartodb_services.mapzen.exceptions import MalformedResult
@@ -88,7 +89,8 @@ class MapzenGeocoderTestCase(unittest.TestCase):
    MALFORMED_RESPONSE = """{"manolo": "escobar"}"""

    def setUp(self):
-        self.geocoder = MapzenGeocoder('search-XXXXXXX')
+        logger = Mock()
+        self.geocoder = MapzenGeocoder('search-XXXXXXX', logger)

    def test_geocode_address_with_valid_params(self, req_mock):
        req_mock.register_uri('GET', self.MAPZEN_GEOCODER_URL,
--- a/server/lib/python/cartodb_services/test/test_mapzenisolines.py
+++ b/server/lib/python/cartodb_services/test/test_mapzenisolines.py
@@ -1,4 +1,5 @@
 import unittest
+from mock import Mock
 from cartodb_services.mapzen import MapzenIsolines
 from math import radians, cos, sin, asin, sqrt

@@ -10,6 +11,7 @@ It uses a mocked client, which returns the cost based on a very simple model:
 just proportional to the distance from origin to the target point.
 """

+
 class MatrixClientMock():

    def __init__(self, speed):
@@ -67,7 +69,7 @@ class MapzenIsolinesTestCase(unittest.TestCase):
    def setUp(self):
        speed = 4 # in km/h
        matrix_client = MatrixClientMock(speed)
-        self.mapzen_isolines = MapzenIsolines(matrix_client)
+        self.mapzen_isolines = MapzenIsolines(matrix_client, Mock())

    def test_calculate_isochrone(self):
        origin = {"lat":40.744014,"lon":-73.990508}
--- a/server/lib/python/cartodb_services/test/test_mapzenrouting.py
+++ b/server/lib/python/cartodb_services/test/test_mapzenrouting.py
@@ -6,6 +6,7 @@ import requests_mock
 import re
 from nose.tools import assert_raises
 from urlparse import urlparse, parse_qs
+from mock import Mock

 from cartodb_services.mapzen import MapzenRouting, MapzenRoutingResponse
 from cartodb_services.mapzen.exceptions import WrongParams
@@ -99,7 +100,8 @@ class MapzenRoutingTestCase(unittest.TestCase):
    MALFORMED_RESPONSE = """{"manolo": "escobar"}"""

    def setUp(self):
-        self.routing = MapzenRouting('api_key')
+        logger = Mock()
+        self.routing = MapzenRouting('api_key', logger)
        self.url = MapzenRouting.PRODUCTION_ROUTING_BASE_URL

    def test_calculate_simple_routing_with_valid_params(self, req_mock):