From e1d8367d880373f0be31f3ac4e608910567162fa Mon Sep 17 00:00:00 2001 From: Denis Makogon Date: Mon, 12 Dec 2016 23:52:40 +0200 Subject: [PATCH] Issue #13: Improve logging in controllers Implements: #13 --- picasso/api/controllers/apps.py | 87 ++++++++++++----- picasso/api/controllers/routes.py | 143 +++++++++++++++++----------- picasso/api/controllers/runnable.py | 17 +++- picasso/common/persistence.py | 22 ++--- picasso/models/app.py | 15 +++ 5 files changed, 188 insertions(+), 96 deletions(-) diff --git a/picasso/api/controllers/apps.py b/picasso/api/controllers/apps.py index 85b83f5..91a8416 100644 --- a/picasso/api/controllers/apps.py +++ b/picasso/api/controllers/apps.py @@ -38,19 +38,20 @@ class AppV1Controller(controller.ServiceController): - application/json responses: "200": - description: successful operation. Return "apps" JSON + description: Successful operation\ "401": - description: Not authorized. + description: Not authorized """ c = config.Config.config_instance() log, fnclient = c.logger, c.functions_client project_id = request.match_info.get('project_id') - log.info("Listing apps for project: {}".format(project_id)) + log.info("[{}] - Listing apps".format(project_id)) stored_apps = await app_model.Apps.find_by(project_id=project_id) final = [] for app in stored_apps: fn_app = await fnclient.apps.show(app.name, loop=c.event_loop) final.append(app_view.AppView(app, fn_app).view()) + log.info("[{}] - Apps found: {}".format(project_id, final)) return web.json_response( data={ self.controller_name: final, @@ -80,9 +81,9 @@ class AppV1Controller(controller.ServiceController): type: string responses: "200": - description: successful operation. Return "app" JSON + description: Successful operation "401": - description: Not authorized. + description: Not authorized "409": description: App exists """ @@ -90,13 +91,15 @@ class AppV1Controller(controller.ServiceController): log, fnclient = c.logger, c.functions_client project_id = request.match_info.get('project_id') data = await request.json() - log.info("Creating an app for project: {} with data {}" + log.info("[{}] - Creating app with data '{}'" .format(project_id, str(data))) app_name = "{}-{}".format( data["app"]["name"], project_id)[:30] if await app_model.Apps.exists(app_name, project_id): + log.info("[{}] - Similar app was found, " + "aborting".format(project_id)) return web.json_response(data={ "error": { "message": "App {0} already exists".format(app_name) @@ -104,13 +107,14 @@ class AppV1Controller(controller.ServiceController): }, status=409) fn_app = await fnclient.apps.create(app_name, loop=c.event_loop) + log.debug("[{}] - Fn app created".format(project_id)) stored_app = await app_model.Apps( name=app_name, project_id=project_id, description=data["app"].get( "description", "App for project {}".format( project_id))).save() - + log.debug("[{}] - App created".format(project_id)) return web.json_response( data={ "app": app_view.AppView(stored_app, fn_app).view(), @@ -129,9 +133,9 @@ class AppV1Controller(controller.ServiceController): - application/json responses: "200": - description: successful operation. Return "app" JSON + description: Successful operation "401": - description: Not authorized. + description: Not authorized "404": description: App not found """ @@ -139,10 +143,12 @@ class AppV1Controller(controller.ServiceController): log, fnclient = c.logger, c.functions_client project_id = request.match_info.get('project_id') app = request.match_info.get('app') - log.info("Requesting an app for project: {} with name {}" + log.info("[{}] - Searching for app with name {}" .format(project_id, app)) if not (await app_model.Apps.exists(app, project_id)): + log.info("[{}] - App not found, " + "aborting".format(project_id)) return web.json_response(data={ "error": { "message": "App {0} not found".format(app), @@ -151,7 +157,18 @@ class AppV1Controller(controller.ServiceController): stored_app = (await app_model.Apps.find_by( project_id=project_id, name=app)).pop() - fn_app = await fnclient.apps.show(app, loop=c.event_loop) + try: + fn_app = await fnclient.apps.show(app, loop=c.event_loop) + log.debug("[{}] - Fn app '{}' found".format(project_id, app)) + except Exception as ex: + log.error("[{}] - Fn app '{}' was not found." + "Reason: \n{}".format(project_id, app, str(ex))) + return web.json_response(data={ + "error": { + "message": getattr(ex, "reason", str(ex)), + } + }, status=getattr(ex, "status", 500)) + log.debug("[{}] - App '{}' found".format(project_id, app)) return web.json_response( data={ "app": app_view.AppView(stored_app, fn_app).view(), @@ -171,29 +188,34 @@ class AppV1Controller(controller.ServiceController): - application/json responses: "200": - description: successful operation. Return "app" JSON + description: Successful operation "401": - description: Not authorized. + description: Not authorized "404": description: App not found """ + c = config.Config.config_instance() + log, fnclient = c.logger, c.functions_client project_id = request.match_info.get('project_id') app_name = request.match_info.get('app') data = await request.json() - + log.info("[{}] - Setting up update procedure " + "with data '{}'".format(project_id, data)) if not (await app_model.Apps.exists(app_name, project_id)): + log.info("[{}] - App not found, " + "aborting".format(project_id)) return web.json_response(data={ "error": { "message": "App {0} not found".format(app_name), } }, status=404) - c = config.Config.config_instance() - fnclient = c.functions_client try: fn_app = await fnclient.apps.update( app_name, loop=c.event_loop, **data) except Exception as ex: + log.info("[{}] - Unable to update app, " + "aborting. Reason: \n{}".format(project_id, str(ex))) return web.json_response(data={ "error": { "message": getattr(ex, "reason", str(ex)), @@ -202,8 +224,8 @@ class AppV1Controller(controller.ServiceController): stored_app = (await app_model.Apps.find_by( project_id=project_id, name=app_name)).pop() - c.logger.info("Updating app {} for project: {} with data {}" - .format(app_name, project_id, str(data))) + log.info("[{}] - Updating app {} with data {}" + .format(project_id, app_name, str(data))) return web.json_response( data={ "app": app_view.AppView(stored_app, fn_app).view(), @@ -223,27 +245,39 @@ class AppV1Controller(controller.ServiceController): - application/json responses: "200": - description: successful operation. Return empty JSON + description: Successful operation "401": - description: Not authorized. + description: Not authorized "404": - description: App does not exist + description: App not found """ project_id = request.match_info.get('project_id') app = request.match_info.get('app') c = config.Config.config_instance() - fnclient = c.functions_client + log, fnclient = c.logger, c.functions_client if not (await app_model.Apps.exists(app, project_id)): + log.info("[{}] - App not found, " + "aborting".format(project_id)) return web.json_response(data={ "error": { "message": "App {0} not found".format(app), } }, status=404) - - fn_app = await fnclient.apps.show(app, loop=c.event_loop) - fn_app_routes = await fn_app.routes.list(loop=c.event_loop) + try: + fn_app = await fnclient.apps.show(app, loop=c.event_loop) + fn_app_routes = await fn_app.routes.list(loop=c.event_loop) + except Exception as ex: + log.info("[{}] - Unable to get app, " + "aborting. Reason: \n{}".format(project_id, str(ex))) + return web.json_response(data={ + "error": { + "message": getattr(ex, "reason", str(ex)), + } + }, status=getattr(ex, "status", 500)) if fn_app_routes: + log.info("[{}] - App has routes, unable to delete it, " + "aborting".format(project_id)) return web.json_response(data={ "error": { "message": ("Unable to delete app {} " @@ -253,8 +287,9 @@ class AppV1Controller(controller.ServiceController): await app_model.Apps.delete( project_id=project_id, name=app) + log.debug("[{}] - App model entry gone".format(project_id)) await fnclient.apps.delete(app, loop=c.event_loop) - + log.debug("[{}] - Fn app deleted".format(project_id)) return web.json_response( data={ "message": "App successfully deleted", diff --git a/picasso/api/controllers/routes.py b/picasso/api/controllers/routes.py index b2f3d06..420c0a3 100644 --- a/picasso/api/controllers/routes.py +++ b/picasso/api/controllers/routes.py @@ -41,21 +41,23 @@ class AppRouteV1Controller(controller.ServiceController): - application/json responses: "200": - description: Successful operation. Return "routes" JSON + description: Successful operation "401": - description: Not authorized. + description: Not authorized "404": - description: App does not exist + description: App not found """ c = config.Config.config_instance() log, fnclient = c.logger, c.functions_client project_id = request.match_info.get('project_id') app = request.match_info.get('app') - log.info("Listing app {} routes for project: {}." + log.info("[{}] - Listing app '{}' routes" .format(app, project_id)) if not (await app_model.Apps.exists(app, project_id)): + log.info("[{}] - App not found, " + "aborting".format(project_id)) return web.json_response(data={ "error": { "message": "App {0} not found".format(app), @@ -64,16 +66,16 @@ class AppRouteV1Controller(controller.ServiceController): fn_app_routes = (await (await fnclient.apps.show( app, loop=c.event_loop)).routes.list(loop=c.event_loop)) - + log.debug("[{}] - Fn routes found".format(project_id)) for fn_route in fn_app_routes: stored_route = (await app_model.Routes.find_by( app_name=app, project_id=project_id, path=fn_route.path)).pop() + log.debug("[{}] - App route '{}' model " + "found".format(project_id, fn_route.path)) setattr(fn_route, "is_public", stored_route.public) - log.info("Listing app {} routes for project: {}." - .format(app, project_id)) return web.json_response(data={ "routes": app_view.AppRouteView(project_id, app, @@ -109,11 +111,11 @@ class AppRouteV1Controller(controller.ServiceController): type: boolean responses: "200": - description: Successful operation. Return "route" JSON + description: Successful operation "401": - description: Not authorized. + description: Not authorized "404": - description: App does not exist + description: App not found "409": description: App route exists """ @@ -123,6 +125,8 @@ class AppRouteV1Controller(controller.ServiceController): app = request.match_info.get('app') if not (await app_model.Apps.exists(app, project_id)): + log.info("[{}] - App not found, " + "aborting".format(project_id)) return web.json_response(data={ "error": { "message": "App {0} not found".format(app), @@ -137,6 +141,8 @@ class AppRouteV1Controller(controller.ServiceController): try: fn_app = await fnclient.apps.show(app, loop=c.event_loop) except Exception as ex: + log.info("[{}] - App not found, " + "aborting".format(project_id)) return web.json_response(data={ "error": { "message": getattr(ex, "reason", str(ex)), @@ -145,6 +151,9 @@ class AppRouteV1Controller(controller.ServiceController): try: await fn_app.routes.show(path, loop=c.event_loop) + log.info("[{}] - Unable to create route. " + "App route '{}' already " + "exists, aborting".format(project_id, path)) return web.json_response(data={ "error": { "message": ( @@ -154,6 +163,8 @@ class AppRouteV1Controller(controller.ServiceController): } }, status=409) except Exception as ex: + log.error("[{}] - Unable to create route. " + "Reason:\n{}".format(project_id, str(ex))) if getattr(ex, "status", 500) != 404: return web.json_response(data={ "error": { @@ -161,27 +172,34 @@ class AppRouteV1Controller(controller.ServiceController): } }, status=getattr(ex, "status", 500)) - new_fn_route = (await fn_app.routes.create( - **data, loop=c.event_loop)) + try: + new_fn_route = (await fn_app.routes.create( + **data, loop=c.event_loop)) + log.debug("[{}] - Fn app created with data " + "'{}'".format(project_id, str(data))) + stored_route = await app_model.Routes( + app_name=app, + project_id=project_id, + path=new_fn_route.path, + is_public=is_public).save() - stored_route = await app_model.Routes( - app_name=app, - project_id=project_id, - path=new_fn_route.path, - is_public=is_public).save() - - log.info("Creating new route in app {} " - "for project: {} with data {}" - .format(app, project_id, str(data))) - - setattr(new_fn_route, "is_public", stored_route.public) - view = app_view.AppRouteView( - project_id, app, [new_fn_route]).view_one() - - return web.json_response(data={ - "route": view, - "message": "App route successfully created" - }, status=200) + setattr(new_fn_route, "is_public", stored_route.public) + view = app_view.AppRouteView( + project_id, app, [new_fn_route]).view_one() + log.info("[{}] - App created with data " + "'{}'".format(project_id, str(view))) + return web.json_response(data={ + "route": view, + "message": "App route successfully created" + }, status=200) + except Exception as ex: + log.error("[{}] - Reason:\n{}".format(project_id, str(ex))) + if getattr(ex, "status", 500) != 404: + return web.json_response(data={ + "error": { + "message": getattr(ex, "reason", str(ex)), + } + }, status=getattr(ex, "status", 500)) @requests.api_action( method='GET', route='{project_id}/apps/{app}/routes/{route}') @@ -195,13 +213,13 @@ class AppRouteV1Controller(controller.ServiceController): - application/json responses: "200": - description: Successful operation. Return "route" JSON + description: Successful operation "401": - description: Not authorized. + description: Not authorized "404": - description: App does not exist + description: App not found "404": - description: App route does not exist + description: App route not found """ c = config.Config.config_instance() log, fnclient = c.logger, c.functions_client @@ -210,6 +228,8 @@ class AppRouteV1Controller(controller.ServiceController): path = request.match_info.get('route') if not (await app_model.Apps.exists(app, project_id)): + log.info("[{}] - App not found, " + "aborting".format(project_id)) return web.json_response(data={ "error": { "message": "App {0} not found".format(app), @@ -221,14 +241,16 @@ class AppRouteV1Controller(controller.ServiceController): route = await fn_app.routes.show( "/{}".format(path), loop=c.event_loop) except Exception as ex: + log.error("[{}] - Exception while attempting get route info. " + "Reason:\n{}".format(project_id, str(ex))) return web.json_response(data={ "error": { "message": getattr(ex, "reason", str(ex)), } }, status=getattr(ex, "status", 500)) - log.info("Requesting route {} in app {} for project: {}" - .format(path, app, project_id)) + log.info("[{}] - Requesting route '{}' in app '{}'" + .format(project_id, path, app, )) stored_route = (await app_model.Routes.find_by( app_name=app, @@ -237,10 +259,14 @@ class AppRouteV1Controller(controller.ServiceController): setattr(route, "is_public", stored_route.public) + view = app_view.AppRouteView( + project_id, app, [route]).view_one() + + log.info("[{}] - Route found with data " + "'{}'".format(project_id, view)) + return web.json_response(data={ - "route": app_view.AppRouteView(project_id, - app, - [route]).view_one(), + "route": view, "message": "App route successfully loaded" }, status=200) @@ -256,9 +282,9 @@ class AppRouteV1Controller(controller.ServiceController): - application/json responses: "200": - description: Successful operation. Return empty JSON + description: Successful operation "401": - description: Not authorized. + description: Not authorized "404": description: App does not exist "404": @@ -274,6 +300,8 @@ class AppRouteV1Controller(controller.ServiceController): .format(path, app, project_id)) if not (await app_model.Apps.exists(app, project_id)): + log.info("[{}] - App not found, " + "aborting".format(project_id)) return web.json_response(data={ "error": { "message": "App {0} not found".format(app), @@ -285,6 +313,8 @@ class AppRouteV1Controller(controller.ServiceController): route = await fn_app.routes.update( "/{}".format(path), loop=c.event_loop, **data) except Exception as ex: + log.error("[{}] - Unable to update app. " + "Reason:\n{}".format(project_id, str(ex))) return web.json_response(data={ "error": { "message": getattr(ex, "reason", str(ex)), @@ -298,11 +328,12 @@ class AppRouteV1Controller(controller.ServiceController): setattr(route, "is_public", stored_route.public) + view = app_view.AppRouteView( + project_id, app, [route]).view_one() + log.info("[{}] - App route update. " + "Route data: {}".format(project_id, view)) return web.json_response(data={ - "route": app_view.AppRouteView(project_id, - app, - [route]).view_one(), - + "route": view, "message": "Route successfully updated", }, status=200) @@ -318,23 +349,25 @@ class AppRouteV1Controller(controller.ServiceController): - application/json responses: "200": - description: Successful operation. Return empty JSON + description: Successful operation "401": - description: Not authorized. + description: Not authorized "404": - description: App does not exist + description: App not found "404": - description: App route does not exist + description: App route not found """ c = config.Config.config_instance() log, fnclient = c.logger, c.functions_client project_id = request.match_info.get('project_id') app = request.match_info.get('app') - path = request.match_info.get('route') - log.info("Deleting route {} in app {} for project: {}" - .format(path, app, project_id)) + path = "/{}".format(request.match_info.get('route')) + log.info("[{}] - Deleting app '{}' route '{}'" + .format(project_id, app, path)) if not (await app_model.Apps.exists(app, project_id)): + log.info("[{}] - App not found, " + "aborting".format(project_id)) return web.json_response(data={ "error": { "message": "App {0} not found".format(app), @@ -343,10 +376,12 @@ class AppRouteV1Controller(controller.ServiceController): try: fn_app = await fnclient.apps.show(app, loop=c.event_loop) - await fn_app.routes.show("/{}".format(path), loop=c.event_loop) - await fn_app.routes.delete("/{}".format(path), loop=c.event_loop) + await fn_app.routes.show(path, loop=c.event_loop) + await fn_app.routes.delete(path, loop=c.event_loop) await app_model.Routes.delete(project_id=project_id, app_name=app) except Exception as ex: + log.error("[{}] - Unable to delete app route '{}'. " + "Reason:\n{}".format(project_id, path, str(ex))) return web.json_response(data={ "error": { "message": getattr(ex, "reason", str(ex)), diff --git a/picasso/api/controllers/runnable.py b/picasso/api/controllers/runnable.py index 3fe24a8..a42ff37 100644 --- a/picasso/api/controllers/runnable.py +++ b/picasso/api/controllers/runnable.py @@ -25,7 +25,7 @@ class RunnableMixin(object): async def run(self, request, **kwargs): c = config.Config.config_instance() - fnclient = c.functions_client + log, fnclient = c.logger, c.functions_client app = request.match_info.get('app') path = "/{}".format(request.match_info.get('route')) @@ -43,6 +43,8 @@ class RunnableMixin(object): result = await fn_app.routes.execute( path, loop=c.event_loop, **data) except Exception as ex: + log.error("Unable to execute route. " + "Reason:\n{}".format(str(ex))) return web.json_response(data={ "error": { "message": getattr(ex, "reason", str(ex)), @@ -82,12 +84,13 @@ class PublicRunnableV1Controller(controller.ServiceController, - application/json responses: "200": - description: successful operation. Return "runnable" JSON + description: Successful operation "404": - description: App does not exist + description: App not found "403": description: Unable to execute private route """ + log = config.Config.config_instance().logger app = request.match_info.get('app') path = "/{}".format(request.match_info.get('route')) routes = await app_model.Routes.find_by( @@ -102,6 +105,7 @@ class PublicRunnableV1Controller(controller.ServiceController, route = routes.pop() if not route.public: + log.info("Unable to execute private route '{}'".format(path)) return web.json_response(data={ "error": { "message": "Unable to execute private " @@ -132,18 +136,21 @@ class RunnableV1Controller(controller.ServiceController, - application/json responses: "401": - description: Not authorized. + description: Not authorized "200": - description: successful operation. Return "runnable" JSON + description: Successful operation "404": description: App not found "404": description: App route not found """ + log = config.Config.config_instance().logger app = request.match_info.get('app') project_id = request.match_info.get('project_id') if not (await app_model.Apps.exists(app, project_id)): + log.info("[{}] - App not found, " + "aborting".format(project_id)) return web.json_response(data={ "error": { "message": "App {0} not found".format(app), diff --git a/picasso/common/persistence.py b/picasso/common/persistence.py index f0023fd..53296fe 100644 --- a/picasso/common/persistence.py +++ b/picasso/common/persistence.py @@ -28,9 +28,9 @@ class BaseDatabaseModel(object): def __init__(self, **kwargs): logger = config.Config.config_instance().logger - logger.info("Attempting to create object class instance " - "'{}' with attributes '{}'" - .format(str(self.__class__), str(kwargs))) + logger.debug("Attempting to create object class instance " + "'{}' with attributes '{}'" + .format(str(self.__class__), str(kwargs))) self.id = uuid.uuid4().hex self.created_at = str(datetime.datetime.now()) self.updated_at = str(datetime.datetime.now()) @@ -44,13 +44,13 @@ class BaseDatabaseModel(object): self.table_name, str(tuple([getattr(self, clmn) for clmn in self.columns])) ) - logger.info("Attempting to save object '{}' " - "using SQL query: {}".format(self.table_name, insert)) + logger.debug("Attempting to save object '{}' " + "using SQL query: {}".format(self.table_name, insert)) async with pool.acquire() as conn: async with conn.cursor() as cur: await cur.execute(insert) await conn.commit() - logger.info("Object saved.") + logger.debug("Object saved.") return self @classmethod @@ -59,13 +59,13 @@ class BaseDatabaseModel(object): logger, pool = c.logger, c.connection.pool delete = cls.DELETE.format( cls.table_name, cls.__define_where(**kwargs)) - logger.info("Attempting to delete object '{}' " - "using SQL query: {}".format(cls.table_name, delete)) + logger.debug("Attempting to delete object '{}' " + "using SQL query: {}".format(cls.table_name, delete)) async with pool.acquire() as conn: async with conn.cursor() as cur: await cur.execute(delete) await conn.commit() - logger.info("Object gone.") + logger.debug("Object gone.") # async def update(self, **kwargs): # async with config.Connection.from_class().acquire() as conn: @@ -99,8 +99,8 @@ class BaseDatabaseModel(object): where = cls.__define_where(**kwargs) select = cls.SELECT.format( cls.table_name, where) - logger.info("Attempting to find object(s) '{}' " - "using SQL : {}".format(cls.table_name, select)) + logger.debug("Attempting to find object(s) '{}' " + "using SQL : {}".format(cls.table_name, select)) async with pool.acquire() as conn: async with conn.cursor() as cur: await cur.execute(select) diff --git a/picasso/models/app.py b/picasso/models/app.py index fa9aa8e..9a2c523 100644 --- a/picasso/models/app.py +++ b/picasso/models/app.py @@ -27,6 +27,15 @@ class Apps(persistence.BaseDatabaseModel): "name" ) + def __str__(self): + return ("".format( + name=self.name, + description=self.description, + id=self.id, + project_id=self.project_id)) + class Routes(persistence.BaseDatabaseModel): @@ -43,3 +52,9 @@ class Routes(persistence.BaseDatabaseModel): @property def public(self): return True if self.is_public else False + + def __str__(self): + return ("".format( + path=self.path, project_id=self.project_id, + app_name=self.app_name, is_public=self.public))