Merge pull request #3 from adsabs/debug

adding logs

scan_explorer_service/manifest_factory.py

@@ -3,7 +3,7 @@
 from scan_explorer_service.models import Article, Page, Collection
 from typing import Union
 from itertools import chain
-from scan_explorer_service.views.view_utils import logger
+import logging 
 
 class ManifestFactoryExtended(ManifestFactory):
     """ Extended manifest factory.
@@ -13,37 +13,36 @@ class ManifestFactoryExtended(ManifestFactory):
     """
 
     def create_manifest(self, item: Union[Article, Collection]):
-        logger.debug(f"Creating manifest for item: {item}") 
+        logging.debug(f"Creating manifest for item: {item}") 
         manifest = self.manifest(
             ident=f'{item.id}/manifest.json', label=item.id)
         manifest.description = item.id
         manifest.add_sequence(self.create_sequence(item))
         for range in self.create_range(item):
             manifest.add_range(range)
-        logger.debug(f"Manifest created: {manifest}") 
+        logging.debug(f"Manifest created: {manifest}") 
         return manifest
 
     def create_sequence(self, item: Union[Article, Collection]):
-        logger.debug(f"Creating sequence for item: {item}") 
+        logging.debug(f"Creating sequence for item: {item}") 
         sequence: Sequence = self.sequence()
-        logger.debug(f"Sequence is: {sequence}. Adding canvases to sequence.") 
+        logging.debug(f"Sequence is: {sequence}. Adding canvases to sequence.") 
         for page in item.pages:
-            logger.debug(f"Adding canvas to sequence: {page}.") 
-            sequence.add_canvas(self.get_or_create_canvas(page))
-
-        logger.debug(f"Final sequence created: {sequence}") 
+            logging.debug(f"Adding canvas to sequence: {page}.") 
+            sequence.add_canvas(self.get_or_create_canvas(page)) 
+        logging.debug(f"Final sequence created: {sequence}") 
         return sequence
 
     def create_range(self, item: Union[Article, Collection]):
-        logger.debug(f"Creating range for item: {item}") 
+        logging.debug(f"Creating range for item: {item}") 
         if isinstance(item, Collection):
             return list(chain(*[self.create_range(article) for article in item.articles]))
 
         range: Range = self.range(ident=item.bibcode, label=item.bibcode)
         for page in item.pages:
-            logger.debug(f"Adding canvas to range: {page}.") 
+            logging.debug(f"Adding canvas to range: {page}.") 
             range.add_canvas(self.get_or_create_canvas(page))
-        logger.debug(f"Range created: {[range]}") 
+        logging.debug(f"Range created: {[range]}") 
         return [range]
 
     def get_canvas_dict(self) -> Dict[str, Canvas]:
@@ -52,7 +51,7 @@ def get_canvas_dict(self) -> Dict[str, Canvas]:
         return self.canvas_dict
 
     def get_or_create_canvas(self, page: Page):
-        logger.debug(f"Getting or creating canvas for page: {page}") 
+        logging.debug(f"Getting or creating canvas for page: {page}") 
         canvas_dict = self.get_canvas_dict()
         if(page.id in canvas_dict.keys()):
             return canvas_dict[page.id]
@@ -71,28 +70,28 @@ def get_or_create_canvas(self, page: Page):
         canvas.add_annotation(annotation)
         canvas_dict[page.id] = canvas
 
-        logger.debug(f"Canvas created: {canvas}") 
+        logging.debug(f"Canvas created: {canvas}") 
         return canvas
 
     def create_image_annotation(self, page: Page):
-        logger.debug(f"Creating image annotation for page: {page}") 
+        logging.debug(f"Creating image annotation for page: {page}") 
         annotation: Annotation = self.annotation(ident=str(page.id))
         image: Image = annotation.image(
             ident=page.image_path, label=f'p. {page.label}', iiif=True)
 
         # Override default image quality and format set by prezi
         image.id = image.id.replace(f'/default.jpg', f'/{page.image_color_quality}.tif')
-        logger.debug(f"Image id: {image.id}") 
+        logging.debug(f"Image id: {image.id}") 
         image.format = page.format
         image.height = page.height
         image.width = page.width
-        logger.debug(f"Image annotation created: {annotation}") 
+        logging.debug(f"Image annotation created: {annotation}") 
         return annotation
 
     def add_search_service(self, manifest: Manifest, search_url: str):
-        logger.debug(f"Adding search services for manifest {manifest} and search url {search_url}") 
+        logging.debug(f"Adding search services for manifest {manifest} and search url {search_url}") 
         context = 'http://iiif.io/api/search/1/context.json'
         profile = 'http://iiif.io/api/search/1/search'
 
         manifest.add_service(ident=search_url, context=context, profile=profile)
-        logger.debug(f"Adding search services for manifest {manifest} and search url {search_url}") 
+        logging.debug(f"Adding search services for manifest {manifest} and search url {search_url}") 

scan_explorer_service/utils/utils.py

@@ -1,16 +1,15 @@
 
 from flask import current_app, url_for
-from scan_explorer_service.views.view_utils import logger
-
+import logging
 
 def url_for_proxy(endpoint: str, **values):
     values['_external'] = False
 
     server, prefix = proxy_url()
-    logger.debug(f"Server is {server} and prefix is {prefix}.") 
+    logging.debug(f"Server is {server} and prefix is {prefix}.") 
     path = url_for(endpoint, **values).lstrip('/')
 
-    logger.debug(f"Url is {server}/{prefix}/{path}.") 
+    logging.debug(f"Url is {server}/{prefix}/{path}.") 
     return f'{server}/{prefix}/{path}'
 
 def proxy_url():

scan_explorer_service/views/image_proxy.py

@@ -10,6 +10,7 @@
 from scan_explorer_service.models import Collection, Page, Article
 from scan_explorer_service.utils.db_utils import item_thumbnail
 from scan_explorer_service.utils.utils import url_for_proxy
+import logging
 
 
 bp_proxy = Blueprint('proxy', __name__, url_prefix='/image')
@@ -19,6 +20,7 @@
 @bp_proxy.route('/iiif/2/<path:path>', methods=['GET'])
 def image_proxy(path):
     """Proxy in between the image server and the user"""
+    logging.debug('######## Starting image proxy ########')
     req_url = urlparse.urljoin(f'{current_app.config.get("IMAGE_API_BASE_URL")}/', path)
     req_headers = {key: value for (key, value) in request.headers if key != 'Host' and key != 'Accept'}
 
@@ -27,6 +29,7 @@ def image_proxy(path):
 
     r = requests.request(request.method, req_url, params=request.args, stream=True,
                          headers=req_headers, allow_redirects=False, data=request.form)
+    logging.debug('Response = {r}')
 
     excluded_headers = ['content-encoding','content-length', 'transfer-encoding', 'connection']
     headers = [(name, value) for (name, value) in r.headers.items() if name.lower() not in excluded_headers]
@@ -35,24 +38,32 @@ def image_proxy(path):
     def generate():
         for chunk in r.raw.stream(decode_content=False):
             yield chunk
-
+    logging.debug('######## Ending image proxy ########')
     return Response(generate(), status=r.status_code, headers=headers)
 
 
 @advertise(scopes=['api'], rate_limit=[5000, 3600*24])
 @bp_proxy.route('/thumbnail', methods=['GET'])
 def image_proxy_thumbnail():
     """Helper to generate the correct url for a thumbnail given an ID and type"""
+
+    logging.debug('######## Starting image/thumbnail ########')
     try:
         id = request.args.get('id')
         type = request.args.get('type')
+        logging.debug(f"Id {id}, Type {type}")
         with current_app.session_scope() as session:
             thumbnail_path = item_thumbnail(session, id, type)
+            logging.debug(f"Thumbnail path {thumbnail_path}")
             path = urlparse.urlparse(thumbnail_path).path
+
             remove = urlparse.urlparse(url_for_proxy('proxy.image_proxy', path='')).path
             path = path.replace(remove, '')
+            logging.debug(f"Path {path}")
+            logging.debug('######## Finishing image/thumbnail ########')
             return image_proxy(path)
     except Exception as e:
+        logging.error(f'{e}')
         return jsonify(Message=str(e)), 400
 
 @advertise(scopes=['api'], rate_limit=[5000, 3600*24])

scan_explorer_service/views/manifest.py

@@ -7,8 +7,7 @@
 from scan_explorer_service.open_search import EsFields, text_search_highlight
 from scan_explorer_service.utils.utils import proxy_url, url_for_proxy
 from typing import Union
-from scan_explorer_service.views.view_utils import logger
-
+import logging
 
 bp_manifest = Blueprint('manifest', __name__, url_prefix='/manifest')
 
@@ -28,25 +27,25 @@ def before_request():
 def get_manifest(id: str):
     """ Creates an IIIF manifest from an article or Collection"""
 
-    logger.debug(f"Fetching manifest for item with id : {id}") 
+    logging.debug(f"Fetching manifest for item with id : {id}") 
     with current_app.session_scope() as session:
-        logger.debug(f"Fetching item (Article/Collection).") 
+        logging.debug(f"Fetching item (Article/Collection).") 
         item: Union[Article, Collection] = (
             session.query(Article).filter(Article.id == id).one_or_none()
             or session.query(Collection).filter(Collection.id == id).one_or_none())
 
         if item:
-            logger.debug(f"Item successfully fetched. Creating manifest for item: {item}") 
+            logging.debug(f"Item successfully fetched. Creating manifest for item: {item}") 
             manifest = manifest_factory.create_manifest(item)
-            logger.debug(f"Getting url for proxy for endpoint manifest.search and id {id}") 
+            logging.debug(f"Getting url for proxy for endpoint manifest.search and id {id}") 
             search_url = url_for_proxy('manifest.search', id=id)
-            logger.debug(f"Getting url for proxy for endpoint manifest.search and id {id}")  
+            logging.debug(f"Getting url for proxy for endpoint manifest.search and id {id}")  
             manifest_factory.add_search_service(manifest, search_url)
-            logger.debug(f"Manifest generated successfully for ID: {id}")
+            logging.debug(f"Manifest generated successfully for ID: {id}")
 
             return manifest.toJSON(top=True)
         else:
-            logger.debug(f"Item not found for article with id: {id}") 
+            logging.debug(f"Item not found for article with id: {id}") 
             return jsonify(exception='Article not found'), 404
 
 

scan_explorer_service/views/metadata.py

@@ -7,6 +7,7 @@
 from scan_explorer_service.views.view_utils import ApiErrors
 from scan_explorer_service.open_search import EsFields, page_os_search, aggregate_search, page_ocr_os_search
 import requests
+import logging 
 
 bp_metadata = Blueprint('metadata', __name__, url_prefix='/metadata')
 
@@ -15,20 +16,31 @@
 @bp_metadata.route('/article/extra/<string:bibcode>', methods=['GET'])
 def article_extra(bibcode: str):
     """Route that fetches additional metadata about an article from the ADS search service """
+
+    logging.debug(f"######## Starting /article/extra endpoint. ######")
+
     auth_token = current_app.config.get('ADS_SEARCH_SERVICE_TOKEN')
     ads_search_service = current_app.config.get('ADS_SEARCH_SERVICE_URL')
+
     if auth_token and ads_search_service:
+        logging.debug(f"Auth token {auth_token[::3]} and ads service {ads_search_service} fetched.")
         try:
             params = {'q': f'bibcode:{bibcode}', 'fl':'title,author'}   
             headers = {'Authorization': f'Bearer {auth_token}'}
             response = requests.get(ads_search_service, params, headers=headers).json()
+            logging.debug(f"Response {response}")
             docs = response.get('response').get('docs')
+            logging.debug(f"Docs {docs}")
 
             if docs:
+                logging.debug(f"Successful! Doc {docs[0]}")
                 return docs[0]
         except:
+            logging.debug(f"Failed to retrieve external ADS article metadata")
             return jsonify(message='Failed to retrieve external ADS article metadata'), 500
 
+    logging.debug(f"######## Ending /article/extra endpoint. ######")
+
     return {}
 
 @advertise(scopes=['api'], rate_limit=[300, 3600*24])
@@ -123,9 +135,13 @@ def put_page():
 @bp_metadata.route('/article/search', methods=['GET'])
 def article_search():
     """Search for an article using one or some of the available keywords"""
+
+    logging.debug(f"######## Starting /article/search endpoint. ######")
     try:
         qs, qs_dict, page, limit, sort = parse_query_args(request.args)
+        logging.debug(f"qs={qs}, qs_dict={qs_dict}, page={page}, limit={limit}, sort={sort}")
         result = aggregate_search(qs, EsFields.article_id, page, limit, sort)
+        logging.debug(f"result = {result}")
         text_query = ''
         if SearchOptions.FullText.value in qs_dict.keys():
             text_query = qs_dict[SearchOptions.FullText.value]
@@ -135,8 +151,11 @@ def article_search():
         if article_count == 0:
             collection_count = aggregate_search(qs, EsFields.volume_id, page, limit, sort)['aggregations']['total_count']['value']
             page_count = page_os_search(qs, page, limit, sort)['hits']['total']['value']
+        logging.debug(f"result={result}, page={page}, limit={limit}, text_query={text_query}, collection_count={collection_count}, page_count={page_count}")
+        logging.debug(f"######## Ending /article/search endpoint. ######")
         return jsonify(serialize_os_article_result(result, page, limit, text_query, collection_count, page_count))
     except Exception as e:
+        logging.error(f"{e}")
         return jsonify(message=str(e), type=ApiErrors.SearchError.value), 400
 
 

scan_explorer_service/views/view_utils.py

@@ -1,14 +1,4 @@
 import enum
-import os
-from adsmutils import setup_logging, load_config
-
-# ============================= INITIALIZATION ==================================== #
-
-proj_home = os.path.realpath(os.path.dirname(__file__))
-config = load_config(proj_home=proj_home)
-logger = setup_logging('view_utils.py', proj_home=proj_home,
-                        level=config.get('LOGGING_LEVEL', 'DEBUG'),
-                        attach_stdout=config.get('LOG_STDOUT', False))
 
 class ApiErrors(enum.Enum):
     SearchError = 1