Better logging - new level and requests logging

- Logging requests using before_request
- new log level - Trace for more verbose data
- Some minor changes

app.py

@@ -69,8 +69,7 @@ def cli_init_data(env):
 @click.option('-s', '--secret', help="User's secret")
 def cli_users_create(name, password, secret):
     log.info(f"[CMD] Create User: {name}")
-    user = manager.create_admin_user(name, password, secret)
-    log.info(f"[CMD] Created User: {user}")
+    manager.create_admin_user(name, password, secret)
 
 
 @users_cli.command('set-password', help='Sets password for the user')
@@ -79,10 +78,16 @@ def cli_users_create(name, password, secret):
               confirmation_prompt=True)
 def cli_users_set_password(name, password):
     log.info(f"[CMD] Update password for user: {name}")
-    user = manager.update_users_password(name, password)
-    log.info(f"[CMD] Updated password for user: {user}")
+    manager.update_users_password(name, password)
 
 
+@users_cli.command('add-secret', help='Adds secret for the user')
+@click.argument('name')
+@click.option('-s', '--secret', help='Users password', prompt=True, hide_input=True)
+def cli_users_add_secret(name, secret):
+    log.info(f"[CMD] Add secret for the user: {name} ({secret})")
+    manager.add_user_secret(name, secret)
+
 @users_cli.command('delete', help="Deletes user")
 @click.argument('name')
 def cli_users_delete_user(name):
@@ -108,14 +113,13 @@ def cli_users_list():
 @click.argument('name', )
 def cli_course_creates(name):
     log.info(f"[CMD] Create Course: {name}")
-    course = manager.create_course(name)
-    log.info(f"[CMD] Created Course: {course}")
+    manager.create_course(name)
 
 
 @courses_cli.command('list', help="List courses")
 def cli_courses_list():
     log.info(f"[CMD] List Courses")
-    course = manager.list_courses()
+    manager.list_courses()
 
 
 @courses_cli.command(
@@ -125,8 +129,7 @@ def cli_courses_list():
 @click.argument('name', required=False)
 def cli_course_role_creates(course, type, name=None):
     log.info(f"[CMD] Create Role: \"{type}\" in the \"{course}\"")
-    course = manager.create_role(course, role_type=type, name=name)
-    log.info(f"[CMD] Created Course: {course}")
+    manager.create_role(course, role_type=type, name=name)
 
 
 @projects_cli.command('activate', help="activates project")
@@ -134,8 +137,7 @@ def cli_course_role_creates(course, type, name=None):
 @click.option('-c', '--course')
 def cli_projects_activate(project, course):
     log.info(f"[CMD] Activating project: {project} in course {course}")
-    project = manager.activate_project(course, project)
-    log.info(f"[CMD] Project has been activated: {project}")
+    manager.activate_project(course, project)
 
 
 @projects_cli.command('list', help="list projects")

management/data/__init__.py

@@ -7,10 +7,13 @@ from management.data import shared
 from management.data.data_dev import init_dev_data
 from management.data.data_prod import init_prod_data
 from management.data.data_test import init_test_data
+from portal import logger
 from portal.database.models import Course, Role, Secret, Submission, SubmissionState, User
 from portal.service.rest import RestService
 from portal.tools import time
 
+log = logger.get_logger(__name__)
+
 
 class DataManagement(object):
     def __init__(self, app: Flask, db: SQLAlchemy):
@@ -49,7 +52,7 @@ class DataManagement(object):
             name(str): name of the user
         """
         with self.app.app_context():
-            user = self.rest.users.find(name)
+            user = self.rest.find.user(name)
             self.rest.users(user).delete()
 
     def update_users_password(self, name: str, password: str) -> User:
@@ -64,7 +67,8 @@ class DataManagement(object):
             user.set_password(password=password)
             self.db.session.add(user)
             self.db.session.commit()
-        return user
+            log.debug(f"[DATA] User's password updated: {user.log_name}")
+            return user
 
     def create_admin_user(self, name: str, password: str, secret: str = None) -> User:
         """Creates new admin user with username
@@ -82,8 +86,9 @@ class DataManagement(object):
                 password=password)
             if secret:
                 user.secrets.append(Secret(name='admin-secret', value=secret))
+            log.debug(f'[DATA] Created user: {user.log_name}')
             self.db.session.commit()
-        return user
+            return user
 
     def create_course(self, name: str) -> Course:
         """Creates course with associated roles
@@ -94,7 +99,8 @@ class DataManagement(object):
         with self.app.app_context():
             course = self.creator.scaffold_course(codename=name)
             self.db.session.commit()
-        return course
+            log.debug(f'[DATA] Created course: {course.log_name}')
+            return course
 
     def create_role(self, course_name: str, role_type: str, name: str) -> Role:
         """Creates role in the course based on type
@@ -109,7 +115,8 @@ class DataManagement(object):
             role = self.creator.scaffold_role(
                 course, role_type=role_type, name=name)
             self.db.session.commit()
-        return role
+            log.debug(f'[DATA] Created role: {role.log_name}')
+            return role
 
     def list_users(self):
         with self.app.app_context():
@@ -124,6 +131,7 @@ class DataManagement(object):
             project.config.archive_from = None
             project.config.submissions_allowed_to = days_allow_to
             self.rest.projects.write_entity(project)
+            log.info(f"[CMD] Project has been activated: {project.log_name}")
             return project
 
     def list_projects(self, course: str):
@@ -161,3 +169,10 @@ class DataManagement(object):
             for submission in Submission.query.all():
                 Submission.query.filter_by(id=submission.id).delete()
             self.db.session.commit()
+
+    def add_user_secret(self, name, secret):
+        with self.app.app_context():
+            user = self.rest.find.user(name)
+            user.secrets.append(Secret(name='user-cli-secret', value=secret))
+            log.debug(f'[DATA] Created secret for user: {user.log_name}')
+            self.db.session.commit()

migrations/versions/0d5113dee43f_.py

+"""empty message
+
+Revision ID: 0d5113dee43f
+Revises: bd2121c14eaa
+Create Date: 2018-09-23 09:42:45.421006
+
+"""
+from alembic import op
+import sqlalchemy as sa
+
+
+# revision identifiers, used by Alembic.
+revision = '0d5113dee43f'
+down_revision = 'bd2121c14eaa'
+branch_labels = None
+depends_on = None
+
+
+def upgrade():
+    # ### commands auto generated by Alembic - please adjust! ###
+    op.add_column('secret', sa.Column('updated_at', sa.TIMESTAMP(), nullable=True))
+    # ### end Alembic commands ###
+
+
+def downgrade():
+    # ### commands auto generated by Alembic - please adjust! ###
+    op.drop_column('secret', 'updated_at')
+    # ### end Alembic commands ###

portal/__init__.py

@@ -46,10 +46,10 @@ def configure_app(app: Flask, env: str = None,
     app.config.from_object(config_object)
     _load_portal_local(app, env, ignore_local)
     app.config['PORTAL_ENV'] = config_type
-    log.debug("[INIT] Loaded config: ")
     if app.config.get('PORTAL_LOG_CONFIG'):
+        log.trace("[INIT] Loaded config: ")
         for (key, val) in app.config.items():
-            log.debug(f"[CONFIG] {key}={val}")
+            log.trace(f"[CONFIG] {key}={val}")
     return app
 
 
@@ -121,6 +121,13 @@ def create_app(environment: str = None):
     configure_extensions(app)
     configure_async(app)
     rest.register_namespaces(app)
+
+    @app.before_request
+    def __before_request():
+        from flask import request
+        body = request.get_data(as_text=True) if request.data else ''
+        app.logger.debug(f"[{request.method}] {request.url} - {body}")
+
     return app
 
 

portal/config.py

@@ -28,7 +28,6 @@ class Config(object):
     JWT_SECRET_KEY = os.environ.get('JWT_SECRET_KEY') or 'super-safe'
     JWT_REFRESH_TOKEN_EXPIRES = datetime.timedelta(days=30)
     JWT_ACCESS_TOKEN_EXPIRES = datetime.timedelta(hours=1)
-    LOGGER_NAME = "flask"
     API_PREFIX = os.environ.get('PORTAL_API_PREFIX', default="/api/v1.0/")
     CORS_SUPPORT_CREDENTIALS = True
     BROKER_URL = os.getenv('CELERY_BROKER_URL', 'redis://localhost:6379/0')

portal/database/models.py

@@ -31,7 +31,8 @@ def _repr(instance) -> str:
     Returns(str): String representation of the model
     """
     no_include = {'password_hash', 'review', 'course', 'user', 'project', 'group', 'role',
-                  'review_items', 'client', 'EXCLUDED'}
+                  'review_items', 'client', 'EXCLUDED', 'query', 'groups', 'roles', 'secrets',
+                  'courses', 'projects'}
     if 'EXCLUDED' in vars(instance.__class__):
         no_include.update(instance.__class__.EXCLUDED)
     result = f"{instance.__class__.__name__}: "

portal/logger.py

@@ -40,8 +40,10 @@ HANDLERS = {
 LOGGERS = {
     'portal': {'handlers': ['console', 'file'], 'level': 'DEBUG', 'propagate': True},
     'tests': {'handlers': ['console'], 'level': 'DEBUG', 'propagate': True},
-    'management': {'handlers': ['console'], 'level': 'DEBUG', 'propagate': True},
-    'app': {'handlers': ['console'], 'level': 'INFO', 'propagate': True},
+    'management': {'handlers': ['console'], 'level': 'INFO', 'propagate': True},
+    'app': {'handlers': ['console'], 'level': 'DEBUG', 'propagate': True},
+    'flask': {'handlers': ['console'], 'level': 'DEBUG', 'propagate': True},
+    'werkzeug': {'handlers': ['console'], 'level': 'DEBUG', 'propagate': True},
     'storage': {'handlers': ['console'], 'level': 'DEBUG', 'propagate': True},
 }
 
@@ -53,6 +55,19 @@ LOGGING_CONF = {
     'loggers': LOGGERS,
 }
 
+TRACE_LOG_LVL = 9
+
+
+def _trace(self, message, *args, **kws):
+    if self.isEnabledFor(TRACE_LOG_LVL):
+        # Yes, logger takes its '*args' as 'args'.
+        self._log(TRACE_LOG_LVL, message, args, **kws)
+
+
+def add_custom_log_level():
+    logging.addLevelName(TRACE_LOG_LVL, 'TRACE')
+    logging.Logger.trace = _trace
+
 
 def load_config(conf_type=None):
     """Loads config based on the config type
@@ -60,8 +75,9 @@ def load_config(conf_type=None):
         conf_type(str): Config type available (dev, test, prod)
 
     """
-    if conf_type is not None:
-        print("Not implemented yet!")
+    if conf_type == 'test':
+        LOGGING_CONF['loggers']['management']['level'] = 'WARNING'
+    add_custom_log_level()
     dictConfig(LOGGING_CONF)
 
 

portal/rest/errors.py

@@ -8,13 +8,13 @@ from sqlalchemy.exc import SQLAlchemyError
 
 from portal import logger
 from portal.rest import rest_api
-from portal.service.errors import IncorrectCredentialsError, PortalAPIError
+from portal.service.errors import IncorrectCredentialsError, PortalAPIError, UnauthorizedError
 
 log = logger.get_logger(__name__)
 
 
 def load_errors(app: Flask):
-    log.debug("[LOAD] Custom error handlers loaded")
+    log.trace("[LOAD] Custom error handlers loaded")
     for (ex, func) in rest_api.error_handlers.items():
         app.register_error_handler(ex, func)
 
@@ -24,21 +24,21 @@ def default_error_handler():
     return flask.jsonify({'message': 'Default error handler has been triggered'}), 401
 
 
-@rest_api.errorhandler(PortalAPIError)
-def handle_portal_api_error(ex: PortalAPIError):
-    log.error(f"[API] Api error: {ex} ")
-    abort(code=ex.code, message=ex.message)
+@rest_api.errorhandler(UnauthorizedError)
+def handle_unauthorized_error(ex: UnauthorizedError):
+    log.warning(f"[AUTH] {ex.message} ")
+    return flask.jsonify({'message': ex.message, 'error': f'{ex}'}), 401
 
 
 @rest_api.errorhandler(NoAuthorizationError)
 def handle_missing_auth_header(ex: NoAuthorizationError):
-    log.debug(f"[AUTH] Auth headers are missing: {ex} ")
+    log.warning(f"[AUTH] Auth headers are missing: {ex} ")
     return flask.jsonify({'message': 'Auth headers is missing', 'error': f'{ex}'}), 401
 
 
 @rest_api.errorhandler(IncorrectCredentialsError)
 def handle_missing_auth_header(ex: IncorrectCredentialsError):
-    log.debug(f"[AUTH] Credentials are incorrect: {ex} ")
+    log.warning(f"[AUTH] Credentials are incorrect: {ex} ")
     return flask.jsonify({'message': 'Credentials are incorrect', 'error': f'{ex}'}), 401
 
 
@@ -56,9 +56,17 @@ def handle_db_error(ex: SQLAlchemyError):
 
 @rest_api.errorhandler(NotImplementedError)
 def handle_not_implemented_error():
+    log.warning(f"[WARN] Not implemented yet: {ex}")
     return flask.jsonify({'message': f'Not implemented yet!'}), 404
 
 
 @rest_api.errorhandler(storage.errors.KontrStorageError)
 def handle_storage_error(ex: storage.errors.KontrStorageError):
+    log.warning(f"[STORAGE] Storage error: {ex}")
     return flask.jsonify({'message': str(ex)}), 400
+
+
+@rest_api.errorhandler(PortalAPIError)
+def handle_portal_api_error(ex: PortalAPIError):
+    log.error(f"[API] Api error: {ex} ")
+    abort(code=ex.code, message=ex.message)

portal/rest/schemas.py

@@ -302,7 +302,7 @@ class SecretSchema(BaseSchema, Schema):
     """Secret schema
     """
     name = fields.Str()
-    expires_at = fields.LocalDateTime()
+    expires_at = fields.LocalDateTime(allow_none=True)
     client = NESTED('client')
 
 

portal/service/auth.py

@@ -114,7 +114,7 @@ class AuthService:
         return self._find_client_helper(identifier)
 
     def _find_client_helper(self, identifier: str) -> Client:
-        log.debug(f"[LOGIN] Finding client using identifier: {identifier}")
+        log.trace(f"[FIND] Finding client using identifier: {identifier}")
         client = self._rest_service.find.client(identifier, throws=False)
         if not client:
             raise errors.UnauthorizedError(f"[LOGIN] Unknown client identifier {identifier}.")

portal/service/find.py

@@ -42,7 +42,7 @@ class FindService:
                 raise errors.ResourceNotFoundError(resource=resource, res_id=identifier)
             else:
                 return None
-        log.debug(
+        log.trace(
             f"[FIND] Found {resource.capitalize()} for identifier [{identifier}]: {instance}")
         return instance
 

portal/service/general.py

@@ -5,13 +5,11 @@ import abc
 import logging
 
 import flask
-from flask_jwt_extended import get_jwt_identity
 from flask_sqlalchemy import SQLAlchemy
 
 from portal import db
 from portal.database.models import Course
 from portal.database.utils import sql_get_count
-from portal.service import errors
 
 log = logging.getLogger(__name__)
 
@@ -32,15 +30,7 @@ class GeneralService:
 
     @property
     def client(self):
-        identifier = get_jwt_identity()
-        return self._find_client_helper(identifier)
-
-    def _find_client_helper(self, identifier):
-        log.debug(f"[LOGIN] Finding client using identifier: {identifier}")
-        client = self.find.client(identifier, throws=False)
-        if not client:
-            raise errors.UnauthorizedError(f"[LOGIN] Unknown client identifier {identifier}.")
-        return client
+        return self._rest_service.auth.client
 
     @property
     def request(self) -> flask.Request:
@@ -59,6 +49,7 @@ class GeneralService:
         return self.db.session
 
     def find_all(self, *args, **kwargs):
+        log.debug(f"[GET] Find all {self._entity_klass.__name__}: {args} {kwargs}")
         return self._entity_klass.query.all()
 
     def delete(self):
@@ -102,7 +93,7 @@ class GeneralService:
         Args:
             entity(db.Model): Database entity instance
         """
-        log.debug(f"[WRITE] Entity {entity.__class__.__name__}: {entity}")
+        log.trace(f"[WRITE] Entity {entity.__class__.__name__}: {entity}")
         self.db_session.add(entity)
         self.db_session.commit()
 
@@ -112,7 +103,7 @@ class GeneralService:
         Args:
             entity(db.Model): Database entity instance
         """
-        log.debug(f"[DELETE] Entity {entity.__class__.__name__}: {entity}")
+        log.trace(f"[DELETE] Entity {entity.__class__.__name__}: {entity}")
         self.db_session.delete(entity)
         self.db.session.commit()
 
@@ -123,7 +114,7 @@ class GeneralService:
         Returns: Instance of the same object
 
         """
-        log.debug(f"[REFRESH] Entity {entity.__class__.__name__}: {entity}")
+        log.trace(f"[REFRESH] Entity {entity.__class__.__name__}: {entity}")
         self.db.session.refresh(entity)
         return entity
 
@@ -133,7 +124,7 @@ class GeneralService:
             entity: Any db model
         Returns: Instance of the same object
         """
-        log.debug(f"[EXPIRE] Entity {entity.__class__.__name__}: {entity}")
+        log.trace(f"[EXPIRE] Entity {entity.__class__.__name__}: {entity}")
         self.db_session.expire(entity)
         return entity
 

tests/rest/test_clients.py

@@ -28,7 +28,6 @@ def test_client_detail_using_student_cred(client, student_credentials):
     path = f'/client'
     response = utils.make_request(
         client, path, 'get', credentials=student_credentials)
-    print(f"Response: {response.data}")
     assert response.status_code == 200
     assert response.mimetype == 'application/json'
     data = response.json
@@ -40,7 +39,6 @@ def test_client_detail_using_executor_cred(client, worker_credentials):
     path = f'/client'
     response = utils.make_request(
         client, path, 'get', credentials=worker_credentials)
-    print(f"Response: {response.data}")
     assert response.status_code == 200
     assert response.mimetype == 'application/json'
     data = response.json