Added logging

openprocurement/documentservice/__init__.py

@@ -1,52 +1,12 @@
 import gevent.monkey
 gevent.monkey.patch_all()
-import os
-from ConfigParser import ConfigParser
-from base64 import b64encode, b64decode
-from hashlib import sha512
 from libnacl.sign import Signer, Verifier
-from logging import getLogger
+from openprocurement.documentservice.utils import auth_check, Root, add_logging_context, read_users
 from pkg_resources import iter_entry_points
 from pyramid.authentication import BasicAuthAuthenticationPolicy
 from pyramid.authorization import ACLAuthorizationPolicy
 from pyramid.config import Configurator
-from pyramid.security import Allow
-from pytz import timezone
-
-LOGGER = getLogger(__name__)
-TZ = timezone(os.environ['TZ'] if 'TZ' in os.environ else 'Europe/Kiev')
-USERS = {}
-
-
-def auth_check(username, password, request):
-    if username in USERS and USERS[username]['password'] == sha512(password).hexdigest():
-        return ['g:{}'.format(USERS[username]['group'])]
-
-
-class Root(object):
-    def __init__(self, request):
-        pass
-
-    __acl__ = [
-        (Allow, 'g:uploaders', 'upload'),
-        (Allow, 'g:api', 'upload'),
-        ]
-
-
-def read_users(filename):
-    config = ConfigParser()
-    config.read(filename)
-    for i in config.sections():
-        USERS.update(dict([
-            (
-                j,
-                {
-                    'password': k,
-                    'group': i
-                }
-            )
-            for j, k in config.items(i)
-        ]))
+from pyramid.events import ContextFound
 
 
 def main(global_config, **settings):
@@ -59,6 +19,7 @@ def main(global_config, **settings):
         authorization_policy=ACLAuthorizationPolicy(),
         root_factory=Root,
     )
+    config.add_subscriber(add_logging_context, ContextFound)
     config.include('pyramid_exclog')
     config.add_route('register', '/register')
     config.add_route('upload', '/upload')

openprocurement/documentservice/utils.py

@@ -0,0 +1,102 @@
+import os
+from ConfigParser import ConfigParser
+from base64 import b64encode, b64decode
+from datetime import datetime
+from hashlib import sha512
+from json import dumps
+from libnacl.sign import Signer, Verifier
+from logging import getLogger
+from pkg_resources import iter_entry_points
+from pyramid.authentication import BasicAuthAuthenticationPolicy
+from pyramid.authorization import ACLAuthorizationPolicy
+from pyramid.config import Configurator
+from pyramid.security import Allow
+from pytz import timezone
+
+LOGGER = getLogger(__name__)
+TZ = timezone(os.environ['TZ'] if 'TZ' in os.environ else 'Europe/Kiev')
+USERS = {}
+
+
+def auth_check(username, password, request):
+    if username in USERS and USERS[username]['password'] == sha512(password).hexdigest():
+        return ['g:{}'.format(USERS[username]['group'])]
+
+
+class Root(object):
+    def __init__(self, request):
+        pass
+
+    __acl__ = [
+        (Allow, 'g:uploaders', 'upload'),
+        (Allow, 'g:api', 'upload'),
+        ]
+
+
+def read_users(filename):
+    config = ConfigParser()
+    config.read(filename)
+    for i in config.sections():
+        USERS.update(dict([
+            (
+                j,
+                {
+                    'password': k,
+                    'group': i
+                }
+            )
+            for j, k in config.items(i)
+        ]))
+
+
+def add_logging_context(event):
+    request = event.request
+    params = {
+        'API_KEY': request.registry.apikey,
+        'DOC_KEY': request.registry.apikey,
+        'TAGS': 'python,docs',
+        'CURRENT_URL': request.url,
+        'CURRENT_PATH': request.path_info,
+        'REMOTE_ADDR': request.remote_addr or '',
+        'USER_AGENT': request.user_agent or '',
+        'REQUEST_ID': request.environ.get('REQUEST_ID', ''),
+        'CLIENT_REQUEST_ID': request.headers.get('X-Client-Request-ID', ''),
+    }
+    if request.params:
+        params['PARAMS'] = str(dict(request.params))
+    if request.matchdict:
+        for i, j in request.matchdict.items():
+            params[i.upper()] = j
+
+    request.logging_context = params
+
+
+def update_logging_context(request, params):
+    for x, j in params.items():
+        request.logging_context[x.upper()] = j
+
+
+def context_unpack(request, msg, params=None):
+    if params:
+        update_logging_context(request, params)
+    logging_context = request.logging_context
+    journal_context = msg
+    for key, value in logging_context.items():
+        journal_context["JOURNAL_" + key] = value
+    journal_context['JOURNAL_TIMESTAMP'] = datetime.now(TZ).isoformat()
+    return journal_context
+
+
+def error_handler(request, status, error):
+    params = {
+        'ERROR_STATUS': status
+    }
+    for key, value in error.items():
+        params['ERROR_{}'.format(key)] = value
+    LOGGER.info('Error on processing request "{}"'.format(dumps(error)),
+                extra=context_unpack(request, {'MESSAGE_ID': 'error_handler'}, params))
+    request.response.status = status
+    return {
+        "status": "error",
+        "errors": [error]
+    }

openprocurement/documentservice/views.py

@@ -3,20 +3,21 @@
 from time import time
 from urllib import quote, unquote
 from openprocurement.documentservice.storage import StorageRedirect, HashInvalid, KeyNotFound, NoContent, ContentUploaded
+from openprocurement.documentservice.utils import error_handler, context_unpack
+from logging import getLogger
 
+LOGGER = getLogger(__name__)
 EXPIRES = 300
 
 
 @view_config(route_name='register', renderer='json', request_method='POST', permission='upload')
 def register_view(request):
     if 'hash' not in request.POST:
-        request.response.status = 404
-        return {
-            "status": "error",
-            "errors": [{"location": "body", "name": "hash", "description": "Not Found"}]
-        }
+        return error_handler(request, 404, {"location": "body", "name": "hash", "description": "Not Found"})
     md5 = request.POST['hash']
     uuid = request.registry.storage.register(md5)
+    LOGGER.info('Registered new document upload {}'.format(uuid),
+                extra=context_unpack(request, {'MESSAGE_ID': 'registered_upload'}, {'doc_id': uuid, 'doc_hash': md5}))
     signature = quote(b64encode(request.registry.signer.signature(uuid)))
     upload_url = request.route_url('upload_file', doc_id=uuid, _query={'Signature': signature, 'KeyID': request.registry.dockey}, _host=request.registry.upload_host or request.domain)
     signature = quote(b64encode(request.registry.signer.signature("{}\0{}".format(uuid, md5))))
@@ -29,13 +30,11 @@ def register_view(request):
 @view_config(route_name='upload', renderer='json', request_method='POST', permission='upload')
 def upload_view(request):
     if 'file' not in request.POST or not hasattr(request.POST['file'], 'filename'):
-        request.response.status = 404
-        return {
-            "status": "error",
-            "errors": [{"location": "body", "name": "file", "description": "Not Found"}]
-        }
+        return error_handler(request, 404, {"location": "body", "name": "file", "description": "Not Found"})
     post_file = request.POST['file']
     uuid, md5, content_type, filename = request.registry.storage.upload(post_file)
+    LOGGER.info('Uploaded new document {}'.format(uuid),
+                extra=context_unpack(request, {'MESSAGE_ID': 'uploaded_new_document'}, {'doc_id': uuid, 'doc_hash': md5}))
     expires = int(time()) + EXPIRES
     signature = quote(b64encode(request.registry.signer.signature("{}\0{}".format(uuid, md5))))
     url = request.route_url('get', doc_id=uuid, _query={'Signature': signature, 'KeyID': request.registry.dockey}, _host=request.registry.get_host or request.domain)
@@ -48,65 +47,35 @@ def upload_view(request):
 @view_config(route_name='upload_file', renderer='json', request_method='POST', permission='upload')
 def upload_file_view(request):
     if 'file' not in request.POST or not hasattr(request.POST['file'], 'filename'):
-        request.response.status = 404
-        return {
-            "status": "error",
-            "errors": [{"location": "body", "name": "file", "description": "Not Found"}]
-        }
+        return error_handler(request, 404, {"location": "body", "name": "file", "description": "Not Found"})
     uuid = request.matchdict['doc_id']
     keyid = request.GET.get('KeyID', request.registry.dockey)
     if keyid not in request.registry.dockeyring:
-        request.response.status = 403
-        return {
-            "status": "error",
-            "errors": [{"location": "url", "name": "KeyID", "description": "Key Id does not exist"}]
-        }
+        return error_handler(request, 403, {"location": "url", "name": "KeyID", "description": "Key Id does not exist"})
     key = request.registry.dockeyring.get(keyid)
     if 'Signature' not in request.GET:
-        request.response.status = 403
-        return {
-            "status": "error",
-            "errors": [{"location": "url", "name": "Signature", "description": "Not Found"}]
-        }
+        return error_handler(request, 403, {"location": "url", "name": "Signature", "description": "Not Found"})
     signature = request.GET['Signature']
     try:
         signature = b64decode(unquote(signature))
     except TypeError:
-        request.response.status = 403
-        return {
-            "status": "error",
-            "errors": [{"location": "url", "name": "Signature", "description": "Signature invalid"}]
-        }
+        return error_handler(request, 403, {"location": "url", "name": "Signature", "description": "Signature invalid"})
     try:
         if uuid != key.verify(signature + uuid.encode("utf-8")):
             raise ValueError
     except ValueError:
-        request.response.status = 403
-        return {
-            "status": "error",
-            "errors": [{"location": "url", "name": "Signature", "description": "Signature does not match"}]
-        }
+        return error_handler(request, 403, {"location": "url", "name": "Signature", "description": "Signature does not match"})
     post_file = request.POST['file']
     try:
         uuid, md5, content_type, filename = request.registry.storage.upload(post_file, uuid)
     except KeyNotFound:
-        request.response.status = 404
-        return {
-            "status": "error",
-            "errors": [{"location": "url", "name": "doc_id", "description": "Not Found"}]
-        }
+        return error_handler(request, 404, {"location": "url", "name": "doc_id", "description": "Not Found"})
     except ContentUploaded:
-        request.response.status = 403
-        return {
-            "status": "error",
-            "errors": [{"location": "url", "name": "doc_id", "description": "Content already uploaded"}]
-        }
+        return error_handler(request, 403, {"location": "url", "name": "doc_id", "description": "Content already uploaded"})
     except HashInvalid:
-        request.response.status = 403
-        return {
-            "status": "error",
-            "errors": [{"location": "body", "name": "file", "description": "Invalid checksum"}]
-        }
+        return error_handler(request, 403, {"location": "body", "name": "file", "description": "Invalid checksum"})
+    LOGGER.info('Uploaded document {}'.format(uuid),
+                extra=context_unpack(request, {'MESSAGE_ID': 'uploaded_document'}, {'doc_hash': md5}))
     expires = int(time()) + EXPIRES
     signature = quote(b64encode(request.registry.signer.signature("{}\0{}".format(uuid, md5))))
     url = request.route_url('get', doc_id=uuid, _query={'Signature': signature, 'KeyID': request.registry.dockey}, _host=request.registry.get_host or request.domain)
@@ -121,61 +90,33 @@ def get_view(request):
     now = int(time())
     expires = request.GET.get('Expires')
     if expires and expires.isdigit() and int(expires) < now:
-        request.response.status = 403
-        return {
-            "status": "error",
-            "errors": [{"location": "url", "name": "Expires", "description": "Request has expired"}]
-        }
+        return error_handler(request, 403, {"location": "url", "name": "Expires", "description": "Request has expired"})
     keyid = request.GET.get('KeyID', request.registry.dockey)
     if keyid not in (request.registry.apikey, request.registry.dockey) and not expires:
-        request.response.status = 403
-        return {
-            "status": "error",
-            "errors": [{"location": "url", "name": "KeyID", "description": "Key Id does permit to get private document"}]
-        }
+        return error_handler(request, 403, {"location": "url", "name": "KeyID", "description": "Key Id does permit to get private document"})
     if keyid not in request.registry.keyring:
-        request.response.status = 403
-        return {
-            "status": "error",
-            "errors": [{"location": "url", "name": "KeyID", "description": "Key Id does not exist"}]
-        }
+        return error_handler(request, 403, {"location": "url", "name": "KeyID", "description": "Key Id does not exist"})
     mess = "{}\0{}".format(uuid, expires) if expires else uuid
     if request.GET.get('Prefix'):
         mess = '{}/{}'.format(request.GET['Prefix'], mess)
         keyid = '{}/{}'.format(request.GET['Prefix'], uuid)
     key = request.registry.keyring.get(keyid)
     if 'Signature' not in request.GET:
-        request.response.status = 403
-        return {
-            "status": "error",
-            "errors": [{"location": "url", "name": "Signature", "description": "Not Found"}]
-        }
+        return error_handler(request, 403, {"location": "url", "name": "Signature", "description": "Not Found"})
     signature = request.GET['Signature']
     try:
         signature = b64decode(unquote(signature))
     except TypeError:
-        request.response.status = 403
-        return {
-            "status": "error",
-            "errors": [{"location": "url", "name": "Signature", "description": "Signature invalid"}]
-        }
+        return error_handler(request, 403, {"location": "url", "name": "Signature", "description": "Signature invalid"})
     try:
         if mess != key.verify(signature + mess.encode("utf-8")):
             raise ValueError
     except ValueError:
-        request.response.status = 403
-        return {
-            "status": "error",
-            "errors": [{"location": "url", "name": "Signature", "description": "Signature does not match"}]
-        }
+        return error_handler(request, 403, {"location": "url", "name": "Signature", "description": "Signature does not match"})
     try:
         doc = request.registry.storage.get(uuid)
     except KeyNotFound:
-        request.response.status = 404
-        return {
-            "status": "error",
-            "errors": [{"location": "url", "name": "doc_id", "description": "Not Found"}]
-        }
+        return error_handler(request, 404, {"location": "url", "name": "doc_id", "description": "Not Found"})
     except NoContent:
         request.response.status = 204
         request.response.content_type = ''