From 424d20fb588a761e4d1404923b980d15121e1f6c Mon Sep 17 00:00:00 2001 From: Will Ronchetti Date: Thu, 30 Jan 2020 08:32:56 -0500 Subject: [PATCH] Route level logging (#121) * C4-14 add some route level logging * fix sys import * bump version * use deco instead * C4-14 add context so deco will work in some scenarios * add context to dlq_to_primary * unskip deco test * fix schema routes as well * up travis python to 3.6 * revert 3.6 * C4-15 address kents points * C4-14 augment test, add more log statements to esstorage --- pytest.ini | 1 + src/snovault/_version.py | 2 +- src/snovault/aggregated_items.py | 9 +++-- src/snovault/attachment.py | 23 +++++++++---- src/snovault/batchupgrade.py | 16 ++++++--- src/snovault/crud_views.py | 27 +++++++++------ src/snovault/elasticsearch/cached_views.py | 7 +++- src/snovault/elasticsearch/esstorage.py | 3 ++ src/snovault/elasticsearch/indexer.py | 31 ++++++++++------- src/snovault/elasticsearch/indexer_queue.py | 26 ++++++++------ src/snovault/embed.py | 11 +++--- src/snovault/indexing_views.py | 30 +++++++++------- src/snovault/jsongraph.py | 2 ++ src/snovault/jsonld_context.py | 17 +++++---- src/snovault/resource_views.py | 21 ++++++++++-- src/snovault/schema_graph.py | 14 +++++--- src/snovault/schema_views.py | 10 ++++-- src/snovault/tests/test_indexing.py | 4 ++- src/snovault/tests/test_logging.py | 16 +++++++++ src/snovault/util.py | 38 +++++++++++++++++---- 20 files changed, 216 insertions(+), 92 deletions(-) diff --git a/pytest.ini b/pytest.ini index 8a325a84d..f081e073c 100644 --- a/pytest.ini +++ b/pytest.ini @@ -1,4 +1,5 @@ [pytest] +log_cli_level = INFO addopts = --pyargs snovault.tests --instafail diff --git a/src/snovault/_version.py b/src/snovault/_version.py index d536558b5..b53515983 100644 --- a/src/snovault/_version.py +++ b/src/snovault/_version.py @@ -1,4 +1,4 @@ """Version information.""" # The following line *must* be the last in the module, exactly as formatted: -__version__ = "1.3.7" +__version__ = "1.3.8" diff --git a/src/snovault/aggregated_items.py b/src/snovault/aggregated_items.py index d44764881..d4a1471c5 100644 --- a/src/snovault/aggregated_items.py +++ b/src/snovault/aggregated_items.py @@ -1,7 +1,11 @@ +import sys + +from pyramid.httpexceptions import HTTPForbidden +from pyramid.view import view_config + from .calculated import calculated_property from .resources import Item -from pyramid.view import view_config -from pyramid.httpexceptions import HTTPForbidden +from .util import debug_log def includeme(config): @@ -11,6 +15,7 @@ def includeme(config): @view_config(context=Item, permission='view', request_method='GET', name='aggregated-items') +@debug_log def item_view_aggregated_items(context, request): """ View config for aggregated_items. If the current model does not have diff --git a/src/snovault/attachment.py b/src/snovault/attachment.py index f2700d359..a12d381bd 100644 --- a/src/snovault/attachment.py +++ b/src/snovault/attachment.py @@ -1,7 +1,15 @@ +import mimetypes +import uuid from base64 import b64decode from hashlib import md5 from io import BytesIO from mimetypes import guess_type +from urllib.parse import ( + quote, + unquote, +) + +import magic from PIL import Image from pyramid.httpexceptions import ( HTTPNotFound, @@ -10,23 +18,23 @@ from pyramid.response import Response from pyramid.traversal import find_root from pyramid.view import view_config -from urllib.parse import ( - quote, - unquote, -) +from structlog import getLogger + from snovault import ( BLOBS, Item, ) +from .util import debug_log from .validation import ValidationFailure -import magic -import mimetypes -import uuid + def includeme(config): config.scan(__name__) +log = getLogger(__name__) + + class ItemWithAttachment(Item): """ Item base class with attachment blob. @@ -242,6 +250,7 @@ def _update(self, properties, sheets=None): @view_config(name='download', context=ItemWithAttachment, request_method='GET', permission='view', subpath_segments=2) +@debug_log def download(context, request): prop_name, filename = request.subpath try: diff --git a/src/snovault/batchupgrade.py b/src/snovault/batchupgrade.py index e3f3a15e7..c92f9e2a7 100644 --- a/src/snovault/batchupgrade.py +++ b/src/snovault/batchupgrade.py @@ -7,20 +7,23 @@ """ import itertools -import logging -import transaction from copy import deepcopy + +import transaction +from pyramid.traversal import find_resource +from pyramid.view import view_config +from structlog import getLogger + from snovault import ( CONNECTION, STORAGE, UPGRADER, ) -from pyramid.view import view_config -from pyramid.traversal import find_resource from .schema_utils import validate +from .util import debug_log +logger = getLogger(__name__) EPILOG = __doc__ -logger = logging.getLogger(__name__) def includeme(config): @@ -28,6 +31,8 @@ def includeme(config): config.scan(__name__) + + def batched(iterable, n=1): l = len(iterable) for ndx in range(0, l, n): @@ -94,6 +99,7 @@ def update_item(storage, context): @view_config(route_name='batch_upgrade', request_method='POST', permission='import_items') +@debug_log def batch_upgrade(request): request.datastore = 'database' transaction.get().setExtendedInfo('upgrade', True) diff --git a/src/snovault/crud_views.py b/src/snovault/crud_views.py index ee50be7ad..65b9b7d87 100644 --- a/src/snovault/crud_views.py +++ b/src/snovault/crud_views.py @@ -1,26 +1,28 @@ -from past.builtins import basestring from pyramid.settings import asbool -from pyramid.traversal import ( - find_resource, -) -from pyramid.view import view_config +import sys from uuid import ( UUID, uuid4, ) + +import transaction +from pyramid.settings import asbool +from pyramid.view import view_config +from structlog import get_logger + +from .calculated import calculated_property from .interfaces import ( - COLLECTIONS, - CONNECTION, STORAGE, Created, BeforeModified, AfterModified, ) +from .invalidation import add_to_indexing_queue from .resources import ( Collection, Item, ) -from .calculated import calculated_property +from .util import debug_log from .validation import ValidationFailure from .validators import ( no_validate_item_content_patch, @@ -31,10 +33,7 @@ validate_item_content_put, validate_item_content_in_place ) -from .invalidation import add_to_indexing_queue -import transaction -from structlog import get_logger log = get_logger(__name__) @@ -147,6 +146,7 @@ def render_item(request, context, render, return_uri_also=False): @view_config(context=Collection, permission='add_unvalidated', request_method='POST', validators=[no_validate_item_content_post], request_param=['validate=false']) +@debug_log def collection_add(context, request, render=None): '''Endpoint for adding a new Item.''' check_only = asbool(request.params.get('check_only', False)) @@ -185,6 +185,7 @@ def collection_add(context, request, render=None): @view_config(context=Item, permission='index', request_method='GET', validators=[validate_item_content_in_place], request_param=['check_only=true']) +@debug_log def item_edit(context, request, render=None): ''' Endpoint for editing an existing Item. @@ -225,6 +226,7 @@ def item_edit(context, request, render=None): @view_config(context=Item, permission='view', request_method='GET', name='links') +@debug_log def get_linking_items(context, request, render=None): """ Utilize find_uuids_linked_to_item function in PickStorage to find @@ -245,6 +247,7 @@ def get_linking_items(context, request, render=None): @view_config(context=Item, permission='edit', request_method='DELETE') +@debug_log def item_delete_full(context, request, render=None): """ DELETE method that either sets the status of an item to deleted (base @@ -297,8 +300,10 @@ def item_delete_full(context, request, render=None): } + @view_config(context=Item, permission='view', request_method='GET', name='validation-errors') +@debug_log def item_view_validation_errors(context, request): """ View config for validation_errors. If the current model does not have diff --git a/src/snovault/elasticsearch/cached_views.py b/src/snovault/elasticsearch/cached_views.py index 772656a56..0fd43a8bd 100644 --- a/src/snovault/elasticsearch/cached_views.py +++ b/src/snovault/elasticsearch/cached_views.py @@ -1,10 +1,13 @@ """ Cached views used when model was pulled from elasticsearch. """ -from itertools import chain +import sys + from pyramid.httpexceptions import HTTPForbidden from pyramid.view import view_config + from .interfaces import ICachedItem +from ..util import debug_log def includeme(config): @@ -12,6 +15,7 @@ def includeme(config): @view_config(context=ICachedItem, request_method='GET', name='embedded') +@debug_log def cached_view_embedded(context, request): source = context.model.source allowed = set(source['principals_allowed']['view']) @@ -45,6 +49,7 @@ def filter_embedded(embedded, effective_principals): @view_config(context=ICachedItem, request_method='GET', name='object') +@debug_log def cached_view_object(context, request): source = context.model.source allowed = set(source['principals_allowed']['view']) diff --git a/src/snovault/elasticsearch/esstorage.py b/src/snovault/elasticsearch/esstorage.py index 863b3fc43..77e54be8c 100644 --- a/src/snovault/elasticsearch/esstorage.py +++ b/src/snovault/elasticsearch/esstorage.py @@ -330,6 +330,7 @@ def purge_uuid(self, rid, index_name, item_type=None, registry=None): mirror_env = registry.settings['mirror.env.name'] use_aws_auth = registry.settings.get('elasticsearch.aws_auth') mirror_health = ff_utils.get_health_page(ff_env=mirror_env) + log.info('PURGE: attempting to purge %s from mirror storage %s' % (rid, mirror_env)) # if we could not get mirror health, bail here if 'error' in mirror_health: log.error('PURGE: Tried to purge %s from mirror storage but couldn\'t get health page. Is staging up?' % rid) @@ -348,6 +349,8 @@ def purge_uuid(self, rid, index_name, item_type=None, registry=None): log.error('PURGE: Couldn\'t find %s in mirrored ElasticSearch (%s). Continuing.' % (rid, mirror_env)) except Exception as exc: log.error('PURGE: Cannot delete %s in mirrored ElasticSearch (%s). Error: %s Continuing.' % (item_type, mirror_env, str(exc))) + else: + log.info('PURGE: Did not find a mirror env. Continuing.') def __iter__(self, *item_types): query = {'query': { diff --git a/src/snovault/elasticsearch/indexer.py b/src/snovault/elasticsearch/indexer.py index e0eb39bcf..dff03d59b 100644 --- a/src/snovault/elasticsearch/indexer.py +++ b/src/snovault/elasticsearch/indexer.py @@ -1,27 +1,31 @@ +import copy +import datetime +import json +import time +import sys +from timeit import default_timer as timer + +import structlog from elasticsearch.exceptions import ( ConflictError, ConnectionError, TransportError, ) -from ..embed import MissingIndexItemException from pyramid.view import view_config from urllib3.exceptions import ReadTimeoutError -from .interfaces import ( - ELASTIC_SEARCH, - INDEXER, - INDEXER_QUEUE -) + from snovault import ( DBSESSION, STORAGE ) from .indexer_utils import get_namespaced_index, find_uuids_for_indexing -import datetime -import structlog -import time -import copy -import json -from timeit import default_timer as timer +from .interfaces import ( + ELASTIC_SEARCH, + INDEXER, + INDEXER_QUEUE +) +from ..embed import MissingIndexItemException +from ..util import debug_log log = structlog.getLogger(__name__) @@ -63,7 +67,8 @@ def check_sid(sid, max_sid): @view_config(route_name='index', request_method='POST', permission="index") -def index(request): +@debug_log +def index(context, request): # Setting request.datastore here only works because routed views are not traversed. request.datastore = 'database' record = request.json.get('record', False) # if True, make a record in es diff --git a/src/snovault/elasticsearch/indexer_queue.py b/src/snovault/elasticsearch/indexer_queue.py index 8485e5614..2f0de05bb 100644 --- a/src/snovault/elasticsearch/indexer_queue.py +++ b/src/snovault/elasticsearch/indexer_queue.py @@ -1,21 +1,24 @@ ### Class to manage the items for indexing # First round will use a standard SQS queue from AWS without Elasticache. -import boto3 +import datetime import json -import math -import structlog import socket +import sys import time -import datetime +from collections import OrderedDict + +import boto3 +import structlog from pyramid.view import view_config -from pyramid.decorator import reify -from .interfaces import INDEXER_QUEUE, INDEXER_QUEUE_MIRROR + from .indexer_utils import get_uuids_for_types -from collections import OrderedDict +from .interfaces import INDEXER_QUEUE, INDEXER_QUEUE_MIRROR +from ..util import debug_log log = structlog.getLogger(__name__) + def includeme(config): config.add_route('queue_indexing', '/queue_indexing') config.add_route('indexing_status', '/indexing_status') @@ -37,7 +40,8 @@ def includeme(config): @view_config(route_name='queue_indexing', request_method='POST', permission="index") -def queue_indexing(request): +@debug_log +def queue_indexing(context, request): """ Endpoint to queue items for indexing. Takes a POST request with index priviliges which should contain either a list of uuids under "uuids" key @@ -95,7 +99,8 @@ def queue_indexing(request): @view_config(route_name='indexing_status', request_method='GET') -def indexing_status(request): +@debug_log +def indexing_status(context, request): """ Endpoint to check what is currently on the queue. Uses GET requests """ @@ -115,7 +120,8 @@ def indexing_status(request): @view_config(route_name='dlq_to_primary', request_method='GET', permission='index') -def dlq_to_primary(request): +@debug_log +def dlq_to_primary(context, request): """ Endpoint to move all uuids on the DLQ to the primary queue """ diff --git a/src/snovault/embed.py b/src/snovault/embed.py index 3d4f2c39d..e932337e9 100644 --- a/src/snovault/embed.py +++ b/src/snovault/embed.py @@ -1,16 +1,15 @@ +import logging from copy import deepcopy -from .interfaces import CONNECTION -from past.builtins import basestring from posixpath import join + from pyramid.compat import ( native_, unquote_bytes_to_wsgi, ) from pyramid.httpexceptions import HTTPNotFound -from pyramid.exceptions import URLDecodeError -from pyramid.traversal import find_resource -from pyramid.interfaces import IRoutesMapper -import logging + +from .interfaces import CONNECTION + log = logging.getLogger(__name__) diff --git a/src/snovault/indexing_views.py b/src/snovault/indexing_views.py index 5f8cca522..791759b32 100644 --- a/src/snovault/indexing_views.py +++ b/src/snovault/indexing_views.py @@ -1,19 +1,20 @@ from __future__ import unicode_literals -from pyramid.security import ( - Authenticated, - Everyone, - principals_allowed_by_permission, -) + +import sys +from contextlib import contextmanager +from timeit import default_timer as timer + +from pyramid.settings import asbool from pyramid.traversal import resource_path from pyramid.view import view_config -from pyramid.settings import asbool -from timeit import default_timer as timer -from contextlib import contextmanager -from .resources import Item, calc_principals -from .interfaces import STORAGE + +from .elasticsearch.indexer_utils import find_uuids_for_indexing from .embed import make_subrequest +from .interfaces import STORAGE +from .resources import Item, calc_principals +from .util import debug_log from .validation import ValidationFailure -from .elasticsearch.indexer_utils import find_uuids_for_indexing + def includeme(config): config.add_route('indexing-info', '/indexing-info') @@ -73,6 +74,7 @@ def get_rev_linked_items(request, uuid): @view_config(context=Item, name='index-data', permission='index', request_method='GET') +@debug_log def item_index_data(context, request): """ Very important view which is used to calculate all the data indexed in ES @@ -201,7 +203,8 @@ def item_index_data(context, request): @view_config(route_name='indexing-info', permission='index', request_method='GET') -def indexing_info(request): +@debug_log +def indexing_info(context, request): """ Endpoint to check some indexing-related properties of a given uuid, which is provided using the `uuid=` query parameter. This route cannot be defined @@ -243,7 +246,8 @@ def indexing_info(request): @view_config(route_name='max-sid', permission='index', request_method='GET') -def max_sid(request): +@debug_log +def max_sid(context, request): """ Very simple endpoint to return the current maximum sid used in postgres. Might make more sense to define this view in storage.py, but leave it here diff --git a/src/snovault/jsongraph.py b/src/snovault/jsongraph.py index b664a99ef..d155f7614 100644 --- a/src/snovault/jsongraph.py +++ b/src/snovault/jsongraph.py @@ -2,6 +2,7 @@ from snovault.elasticsearch.indexer_utils import get_uuids_for_types from past.builtins import basestring from pyramid.view import view_config +from .util import debug_log def includeme(config): @@ -44,6 +45,7 @@ def item_jsongraph(context, properties): @view_config(context=Root, request_method='GET', name='jsongraph') +@debug_log def jsongraph(context, request): conn = request.registry[CONNECTION] cache = { diff --git a/src/snovault/jsonld_context.py b/src/snovault/jsonld_context.py index 6e2a09c10..9585eb99e 100644 --- a/src/snovault/jsonld_context.py +++ b/src/snovault/jsonld_context.py @@ -1,17 +1,18 @@ -from snovault import ( - TYPES, +import sys +from urllib.parse import ( + quote, + urlparse, ) + from pyramid.events import ( ApplicationCreated, subscriber, ) from pyramid.httpexceptions import HTTPNotFound from pyramid.view import view_config -from urllib.parse import ( - quote, - urlparse, -) -from .util import ensurelist + +from snovault import TYPES +from .util import ensurelist, debug_log def includeme(config): @@ -284,6 +285,7 @@ def ontology_from_schema(schema, prefix, term_path, item_type, class_name, base_ @view_config(route_name='jsonld_context_no_slash', request_method='GET') @view_config(route_name='jsonld_context', request_method='GET') +@debug_log def jsonld_context(context, request): """ Basically a view that list all the terms used on the site in JSON-ld format @@ -292,6 +294,7 @@ def jsonld_context(context, request): @view_config(route_name='jsonld_term', request_method='GET') +@debug_log def jsonld_term(context, request): ontology = request.registry['snovault.jsonld.context'] term = request.matchdict['term'] diff --git a/src/snovault/resource_views.py b/src/snovault/resource_views.py index fd3280e4b..9210c2056 100644 --- a/src/snovault/resource_views.py +++ b/src/snovault/resource_views.py @@ -1,9 +1,11 @@ import sys +from itertools import islice +from urllib.parse import urlencode + from future.utils import ( raise_with_traceback, itervalues, ) -from itertools import islice from past.builtins import basestring from pyramid.exceptions import PredicateMismatch from pyramid.httpexceptions import HTTPNotFound @@ -12,7 +14,7 @@ render_view_to_response, view_config, ) -from urllib.parse import urlencode + from .calculated import calculate_properties from .resources import ( AbstractCollection, @@ -25,15 +27,18 @@ expand_embedded_model, process_aggregated_items, check_es_and_cache_linked_sids, - validate_es_content + validate_es_content, + debug_log, ) + def includeme(config): config.scan(__name__) @view_config(context=AbstractCollection, permission='list', request_method='GET', name='listing') +@debug_log def collection_view_listing_db(context, request): result = {} @@ -70,6 +75,7 @@ def collection_view_listing_db(context, request): @view_config(context=Root, request_method='GET', name='page') +@debug_log def home(context, request): properties = request.embed(request.resource_path(context), '@@object') calculated = calculate_properties(context, request, properties, category='page') @@ -79,6 +85,7 @@ def home(context, request): @view_config(context=Root, request_method='GET', name='object') @view_config(context=AbstractCollection, permission='list', request_method='GET', name='object') +@debug_log def collection_view_object(context, request): properties = context.__json__(request) calculated = calculate_properties(context, request, properties) @@ -87,6 +94,7 @@ def collection_view_object(context, request): @view_config(context=AbstractCollection, permission='list', request_method='GET', name='page') +@debug_log def collection_list(context, request): path = request.resource_path(context) properties = request.embed(path, '@@object') @@ -104,6 +112,7 @@ def collection_list(context, request): @view_config(context=Root, request_method='GET') @view_config(context=AbstractCollection, permission='list', request_method='GET') @view_config(context=Item, permission='view', request_method='GET') +@debug_log def item_view(context, request): frame = request.params.get('frame', 'page') if getattr(request, '__parent__', None) is None: @@ -127,6 +136,7 @@ def item_view(context, request): @view_config(context=Item, permission='view', request_method='GET', name='object') +@debug_log def item_view_object(context, request): """ Render json structure. This is the most basic view and contains the scope @@ -162,6 +172,7 @@ def item_view_object(context, request): @view_config(context=Item, permission='view', request_method='GET', name='embedded') +@debug_log def item_view_embedded(context, request): """ Calculate and return the embedded view for an item. This is an intensive @@ -219,6 +230,7 @@ def item_view_embedded(context, request): @view_config(context=Item, permission='view', request_method='GET', name='page') +@debug_log def item_view_page(context, request): item_path = request.resource_path(context) properties = request.embed(item_path, '@@embedded', as_user=True) @@ -229,6 +241,7 @@ def item_view_page(context, request): @view_config(context=Item, permission='expand', request_method='GET', name='expand') +@debug_log def item_view_expand(context, request): path = request.resource_path(context) properties = request.embed(path, '@@object', as_user=True) @@ -267,6 +280,7 @@ def expand_column(request, obj, subset, path): @view_config(context=Item, permission='view', request_method='GET', name='columns') +@debug_log def item_view_columns(context, request): path = request.resource_path(context) properties = request.embed(path, '@@object') @@ -290,6 +304,7 @@ def item_view_columns(context, request): @view_config(context=Item, permission='view_raw', request_method='GET', name='raw') +@debug_log def item_view_raw(context, request): props = context.properties # only upgrade properties if explicitly requested diff --git a/src/snovault/schema_graph.py b/src/snovault/schema_graph.py index df01c9c0d..2bd4e5c14 100644 --- a/src/snovault/schema_graph.py +++ b/src/snovault/schema_graph.py @@ -1,10 +1,14 @@ +import sys from collections import defaultdict +from subprocess import Popen, PIPE +from xml.sax.saxutils import quoteattr, escape + from past.builtins import basestring from pyramid.response import Response from pyramid.view import view_config -from subprocess import Popen, PIPE -from xml.sax.saxutils import quoteattr, escape + from snovault import TYPES +from .util import debug_log def includeme(config): @@ -77,13 +81,15 @@ def digraph(types, exclude=None): @view_config(route_name='graph_dot', request_method='GET') -def schema_dot(request): +@debug_log +def schema_dot(context, request): dot = digraph(request.registry[TYPES].by_item_type, request.params.getall('exclude')) return Response(dot, content_type='text/vnd.graphviz', charset='utf-8') @view_config(route_name='graph_svg', request_method='GET') -def schema_svg(request): +@debug_log +def schema_svg(context, request): dot = digraph(request.registry[TYPES].by_item_type, request.params.getall('exclude')) p = Popen(['dot', '-Tsvg'], stdin=PIPE, stdout=PIPE, stderr=PIPE) svg, err = p.communicate(dot.encode('utf-8')) diff --git a/src/snovault/schema_views.py b/src/snovault/schema_views.py index a4daa8dca..7e1ed9c8f 100644 --- a/src/snovault/schema_views.py +++ b/src/snovault/schema_views.py @@ -1,13 +1,16 @@ from collections import OrderedDict +from itertools import chain +from urllib.parse import urlparse + from pyramid.httpexceptions import HTTPNotFound from pyramid.view import view_config + from .etag import etag_app_version_effective_principals from .interfaces import ( COLLECTIONS, TYPES, ) -from urllib.parse import urlparse -from itertools import chain +from .util import debug_log def includeme(config): @@ -70,6 +73,7 @@ def _annotated_schema(type_info, request): @view_config(route_name='schema', request_method='GET', decorator=etag_app_version_effective_principals) +@debug_log def schema(context, request): """ /profiles/{type_name}.json -- view for the profile of a specific item type @@ -94,8 +98,10 @@ def schema(context, request): return _annotated_schema(type_info, request) + @view_config(route_name='schemas', request_method='GET', decorator=etag_app_version_effective_principals) +@debug_log def schemas(context, request): """ /profiles/ view for viewing all schemas. Leverages the TypeInfo objects diff --git a/src/snovault/tests/test_indexing.py b/src/snovault/tests/test_indexing.py index 7ca517542..4637e2ac9 100644 --- a/src/snovault/tests/test_indexing.py +++ b/src/snovault/tests/test_indexing.py @@ -70,7 +70,7 @@ def app_settings(wsgi_server_host_port, elasticsearch_server, postgresql_server, return settings -@pytest.yield_fixture(scope='session', params=[True, False]) +@pytest.yield_fixture(scope='session', params=[False, True]) def app(app_settings, request): from snovault import main if request.param: # run tests both with and without mpindexer @@ -1093,6 +1093,8 @@ def test_indexing_esstorage(app, testapp, indexer_testapp): # db get_by_uuid direct returns None by design db_res_direct = app.registry[STORAGE].write.get_by_uuid_direct(test_uuid, namespaced_test_type, TEST_TYPE) assert db_res_direct == None + # delete the test item (should throw no exceptions) + esstorage.purge_uuid(test_uuid, namespaced_test_type) @pytest.mark.flaky(max_runs=2, rerun_filter=delay_rerun) diff --git a/src/snovault/tests/test_logging.py b/src/snovault/tests/test_logging.py index ce29e86f0..788df0152 100644 --- a/src/snovault/tests/test_logging.py +++ b/src/snovault/tests/test_logging.py @@ -5,6 +5,7 @@ from snovault.tests.test_post_put_patch import COLLECTION_URL, item_with_uuid import structlog import json +import time import yaml @@ -67,6 +68,7 @@ def test_telemetry_id_carries_through_logging(testapp, external_tx): assert logger._context.get('telemetry_id') == 'test' assert logger._context.get('log_action') == 'action_test' + def test_logging_basic(testapp, external_tx, capfd): ''' in prod logging setup, an Elasticsearch server is provided. Logs will @@ -95,3 +97,17 @@ def test_logging_basic(testapp, external_tx, capfd): assert '@timestamp' in log_msg assert 'logger' in log_msg assert 'level' in log_msg + + +def test_logging_see_debug_log(testapp, capfd): + """ + Tests that when we hit a route with the @debug_log decorator we see an appropriate log statement + """ + testapp.get('/') # all routes are marked + check_logs = capfd.readouterr()[-1].split('\n') + for record in check_logs: + if not record: + continue + if 'DEBUG_FUNC' in record: + return + raise AssertionError("Did not see 'DEBUG_FUNC' in a log message") diff --git a/src/snovault/util.py b/src/snovault/util.py index 88b1e8e08..ff107e308 100644 --- a/src/snovault/util.py +++ b/src/snovault/util.py @@ -1,12 +1,14 @@ -from past.builtins import basestring -from pyramid.threadlocal import manager as threadlocal_manager -from pyramid.httpexceptions import HTTPForbidden -from .interfaces import CONNECTION, STORAGE, TYPES -from copy import deepcopy +import functools import json -import structlog import sys +from copy import deepcopy +import structlog +from past.builtins import basestring +from pyramid.httpexceptions import HTTPForbidden +from pyramid.threadlocal import manager as threadlocal_manager + +from .interfaces import CONNECTION, STORAGE, TYPES log = structlog.getLogger(__name__) @@ -16,6 +18,30 @@ ################### +def debug_log(func): + """ Decorator that adds some debug output of the view to log that we got there """ + @functools.wraps(func) + def log_decorator(*args, **kwargs): + log_function_call(log, func.__name__) + if not args: + return func(**kwargs) + elif not kwargs: + return func(*args) + return func(*args, **kwargs) + return log_decorator + + +def log_function_call(log_ref, func_name, extra=None): + """ + Logs that we have reached func_name in the application + Can log 'extra' information as well if specified + Helpful in debugging 500 errors on routes and logging entry to any particular function + """ + log_ref.info('DEBUG_FUNC -- Entering view config: %s' % func_name) + if extra: + log_ref.info('DEBUG_FUNC -- Extra info: %s' % extra) + + def select_distinct_values(request, value_path, *from_paths): if isinstance(value_path, basestring): value_path = value_path.split('.')