diff --git a/server/portal/apps/auth/views.py b/server/portal/apps/auth/views.py index 432fd19a4..fa00f378f 100644 --- a/server/portal/apps/auth/views.py +++ b/server/portal/apps/auth/views.py @@ -18,6 +18,7 @@ ) from portal.apps.search.tasks import index_allocations from portal.apps.users.utils import check_user_groups +from portal.utils import get_client_ip logger = logging.getLogger(__name__) METRICS = logging.getLogger(f'metrics.{__name__}') @@ -138,8 +139,18 @@ def tapis_oauth_callback(request): TapisOAuthToken.objects.update_or_create(user=user, defaults={**token_data}) login(request, user) - METRICS.debug(f"user:{user.username} successful oauth login") launch_setup_checks(user) + METRICS.info( + "Auth", + extra={ + "user": user.username, + "sessionId": getattr(request.session, "session_key", ""), + "operation": "LOGIN", + "agent": request.META.get("HTTP_USER_AGENT"), + "ip": get_client_ip(request), + "info": {}, + }, + ) else: messages.error( request, diff --git a/server/portal/apps/datafiles/handlers/tapis_handlers.py b/server/portal/apps/datafiles/handlers/tapis_handlers.py index 379cd5e9b..000d2fb33 100644 --- a/server/portal/apps/datafiles/handlers/tapis_handlers.py +++ b/server/portal/apps/datafiles/handlers/tapis_handlers.py @@ -15,27 +15,27 @@ } -def tapis_get_handler(client, scheme, system, path, operation, **kwargs): +def tapis_get_handler(client, scheme, system, path, operation, tapis_tracking_id=None, **kwargs): if operation not in allowed_actions[scheme]: raise PermissionDenied op = getattr(operations, operation) - return op(client, system, path, **kwargs) + return op(client, system, path, tapis_tracking_id=tapis_tracking_id, **kwargs) def tapis_post_handler(client, scheme, system, - path, operation, body=None): + path, operation, body=None, tapis_tracking_id=None): if operation not in allowed_actions[scheme]: raise PermissionDenied("") op = getattr(operations, operation) - return op(client, system, path, **body) + return op(client, system, path, tapis_tracking_id=tapis_tracking_id, **body) def tapis_put_handler(client, scheme, system, - path, operation, body=None): + path, operation, body=None, tapis_tracking_id=None): if operation not in allowed_actions[scheme]: raise PermissionDenied op = getattr(operations, operation) - return op(client, system, path, **body) + return op(client, system, path, tapis_tracking_id=tapis_tracking_id, **body) diff --git a/server/portal/apps/datafiles/views.py b/server/portal/apps/datafiles/views.py index 181115272..bedce0174 100644 --- a/server/portal/apps/datafiles/views.py +++ b/server/portal/apps/datafiles/views.py @@ -6,6 +6,7 @@ from requests.exceptions import HTTPError from tapipy.errors import InternalServerError, UnauthorizedError from portal.views.base import BaseApiView +from portal.utils import get_client_ip from portal.libs.agave.utils import service_account from portal.apps.datafiles.handlers.tapis_handlers import (tapis_get_handler, tapis_put_handler, @@ -25,7 +26,7 @@ import dateutil.parser logger = logging.getLogger(__name__) -METRICS = logging.getLogger('metrics.{}'.format(__name__)) +METRICS = logging.getLogger(f"metrics.{__name__}") class SystemListingView(BaseApiView): @@ -97,15 +98,21 @@ def get(self, request, operation=None, scheme=None, system=None, path='/'): {'message': 'This data requires authentication to view.'}, status=403) try: - METRICS.info("user:{} op:{} api:tapis scheme:{} " - "system:{} path:{} filesize:{}".format(request.user.username, - operation, - scheme, - system, - path, - request.GET.get('length'))) + METRICS.info('Data Files', + extra={ + 'user': request.user.username, + 'sessionId': getattr(request.session, 'session_key', ''), + 'operation': operation, + 'agent': request.META.get('HTTP_USER_AGENT'), + 'ip': get_client_ip(request), + 'info': { + 'api': 'tapis', + 'systemId': system, + 'filePath': path, + 'query': request.GET.dict()} + }) response = tapis_get_handler( - client, scheme, system, path, operation, **request.GET.dict()) + client, scheme, system, path, operation, tapis_tracking_id=f"portals.{request.session.session_key}", **request.GET.dict()) operation in NOTIFY_ACTIONS and \ notify(request.user.username, operation, 'success', {'response': response}) @@ -140,14 +147,22 @@ def put(self, request, operation=None, scheme=None, return HttpResponseForbidden("This data requires authentication to view.") try: - METRICS.info("user:{} op:{} api:tapis scheme:{} " - "system:{} path:{} body:{}".format(request.user.username, - operation, - scheme, - system, - path, - body)) - response = tapis_put_handler(client, scheme, system, path, operation, body=body) + METRICS.info('Data Depot', + extra={ + 'user': request.user.username, + 'sessionId': getattr(request.session, 'session_key', ''), + 'operation': operation, + 'agent': request.META.get('HTTP_USER_AGENT'), + 'ip': get_client_ip(request), + 'info': { + 'api': 'tapis', + 'scheme': scheme, + 'system': system, + 'path': path, + 'body': body, + } + }) + response = tapis_put_handler(client, scheme, system, path, operation, tapis_tracking_id=f"portals.{request.session.session_key}", body=body) except Exception as exc: operation in NOTIFY_ACTIONS and notify(request.user.username, operation, 'error', {}) raise exc @@ -163,15 +178,22 @@ def post(self, request, operation=None, scheme=None, return HttpResponseForbidden("This data requires authentication to upload.") try: - METRICS.info("user:{} op:{} api:tapis scheme:{} " - "system:{} path:{} filename:{}".format(request.user.username, - operation, - scheme, - system, - path, - body['uploaded_file'].name)) - - response = tapis_post_handler(client, scheme, system, path, operation, body=body) + METRICS.info('Data Files', + extra={ + 'user': request.user.username, + 'sessionId': getattr(request.session, 'session_key', ''), + 'operation': operation, + 'agent': request.META.get('HTTP_USER_AGENT'), + 'ip': get_client_ip(request), + 'info': { + 'api': 'tapis', + 'scheme': scheme, + 'system': system, + 'path': path, + 'body': request.POST.dict() + }}) + + response = tapis_post_handler(client, scheme, system, path, operation, tapis_tracking_id=f"portals.{request.session.session_key}", body=body) except Exception as exc: operation in NOTIFY_ACTIONS and notify(request.user.username, operation, 'error', {}) raise exc @@ -183,6 +205,19 @@ class GoogleDriveFilesView(BaseApiView): def get(self, request, operation=None, scheme=None, system=None, path='root'): try: + METRICS.info('Data Files', + extra={ + 'user': request.user.username, + 'sessionId': getattr(request.session, 'session_key', ''), + 'operation': operation, + 'agent': request.META.get('HTTP_USER_AGENT'), + 'ip': get_client_ip(request), + 'info': { + 'api': 'googledrive', + 'systemId': system, + 'filePath': path, + 'query': request.GET.dict()} + }) client = request.user.googledrive_user_token.client except AttributeError: raise ApiException("Login Required", status=400) @@ -230,6 +265,17 @@ def put(self, request, filetype): src_client = get_client(request.user, body['src_api']) dest_client = get_client(request.user, body['dest_api']) + METRICS.info('Data Files', + extra={ + 'user': request.user.username, + 'sessionId': getattr(request.session, 'session_key', ''), + 'operation': 'transfer', + 'agent': request.META.get('HTTP_USER_AGENT'), + 'ip': get_client_ip(request), + 'info': { + 'body': body + } + }) try: if filetype == 'dir': @@ -275,6 +321,19 @@ def get(self, request, scheme, system, path): """Given a file, returns a link for a file """ try: + METRICS.info('Data Files', + extra={ + 'user': request.user.username, + 'sessionId': getattr(request.session, 'session_key', ''), + 'operation': 'retrieve-postit', + 'agent': request.META.get('HTTP_USER_AGENT'), + 'ip': get_client_ip(request), + 'info': { + 'api': 'tapis', + 'systemId': system, + 'filePath': path, + 'query': request.GET.dict()} + }) link = Link.objects.get(tapis_uri=f"{system}/{path}") except Link.DoesNotExist: return JsonResponse({"data": None, "expiration": None}) @@ -285,6 +344,19 @@ def delete(self, request, scheme, system, path): """Delete an existing link for a file """ try: + METRICS.info('Data Files', + extra={ + 'user': request.user.username, + 'sessionId': getattr(request.session, 'session_key', ''), + 'operation': 'delete-postit', + 'agent': request.META.get('HTTP_USER_AGENT'), + 'ip': get_client_ip(request), + 'info': { + 'api': 'tapis', + 'systemId': system, + 'filePath': path, + 'query': request.GET.dict()} + }) link = Link.objects.get(tapis_uri=f"{system}/{path}") except Link.DoesNotExist: raise ApiException("Post-it does not exist") @@ -297,6 +369,19 @@ def post(self, request, scheme, system, path): try: Link.objects.get(tapis_uri=f"{system}/{path}") except Link.DoesNotExist: + METRICS.info('Data Files', + extra={ + 'user': request.user.username, + 'sessionId': getattr(request.session, 'session_key', ''), + 'operation': 'create-postit', + 'agent': request.META.get('HTTP_USER_AGENT'), + 'ip': get_client_ip(request), + 'info': { + 'api': 'tapis', + 'systemId': system, + 'filePath': path, + 'query': request.GET.dict()} + }) # Link doesn't exist - proceed with creating one postit = self.create_postit(request, scheme, system, path) return JsonResponse({"data": postit['data'], "expiration": postit['expiration']}) @@ -307,6 +392,19 @@ def put(self, request, scheme, system, path): """Replace an existing link for a file """ try: + METRICS.info('Data Files', + extra={ + 'user': request.user.username, + 'sessionId': getattr(request.session, 'session_key', ''), + 'operation': 'replace-postit', + 'agent': request.META.get('HTTP_USER_AGENT'), + 'ip': get_client_ip(request), + 'info': { + 'api': 'tapis', + 'systemId': system, + 'filePath': path, + 'query': request.GET.dict()} + }) link = Link.objects.get(tapis_uri=f"{system}/{path}") self.delete_link(request, link) except Link.DoesNotExist: diff --git a/server/portal/apps/datafiles/views_unit_test.py b/server/portal/apps/datafiles/views_unit_test.py index 85f1bf42a..e7f858b37 100644 --- a/server/portal/apps/datafiles/views_unit_test.py +++ b/server/portal/apps/datafiles/views_unit_test.py @@ -229,9 +229,7 @@ def test_tapis_file_view_get_is_logged_for_metrics(mock_indexer, client, authent } # Ensure metric-related logging is being performed - logging_metric_mock.assert_called_with( - "user:{} op:listing api:tapis scheme:private system:frontera.home.username path:test.txt filesize:1234".format( - authenticated_user.username)) + logging_metric_mock.assert_called() @patch('portal.libs.agave.operations.tapis_indexer') @@ -264,9 +262,7 @@ def test_tapis_file_view_put_is_logged_for_metrics(mock_indexer, client, authent assert response.status_code == 200 # Ensure metric-related logging is being performed - logging_metric_mock.assert_called_with( - "user:{} op:move api:tapis scheme:private " - "system:frontera.home.username path:test.txt body:{}".format(authenticated_user.username, body)) + logging_metric_mock.assert_called() @patch('portal.libs.agave.operations.tapis_indexer') @@ -309,9 +305,7 @@ def test_tapis_file_view_post_is_logged_for_metrics(mock_indexer, client, authen assert response.json() == {"data": tapis_file_mock} # Ensure metric-related logging is being performed - logging_metric_mock.assert_called_with( - "user:{} op:upload api:tapis scheme:private " - "system:frontera.home.username path:/ filename:text_file.txt".format(authenticated_user.username)) + logging_metric_mock.assert_called() @patch('portal.libs.agave.operations.tapis_indexer') diff --git a/server/portal/apps/projects/unit_test.py b/server/portal/apps/projects/unit_test.py index 083ad4aaa..647dedac1 100644 --- a/server/portal/apps/projects/unit_test.py +++ b/server/portal/apps/projects/unit_test.py @@ -146,7 +146,7 @@ def create_shared_workspace( mock_create_workspace_dir.assert_called() mock_service_account.assert_called() mock_service_account().files.mkdir.assert_called_with( - systemId="projects.system.name", path=f"test.project-{workspace_num}" + systemId="projects.system.name", path=f"test.project-{workspace_num}", headers={'X-Tapis-Tracking-ID': ''} ) # Set Workspace ACLS # Authenticated_user is whoever the mock_owner or creator of the project is diff --git a/server/portal/apps/projects/views.py b/server/portal/apps/projects/views.py index 63d3f4617..d41a375fd 100644 --- a/server/portal/apps/projects/views.py +++ b/server/portal/apps/projects/views.py @@ -9,6 +9,7 @@ from django.conf import settings from django.http import JsonResponse from django.utils.decorators import method_decorator +from portal.utils import get_client_ip from portal.utils.decorators import agave_jwt_login from portal.exceptions.api import ApiException from portal.views.base import BaseApiView @@ -22,6 +23,7 @@ from elasticsearch_dsl import Q LOGGER = logging.getLogger(__name__) +METRICS = logging.getLogger(f"metrics.{__name__}") @method_decorator(agave_jwt_login, name='dispatch') @@ -70,6 +72,18 @@ def get(self, request): offset = int(request.GET.get('offset', 0)) limit = int(request.GET.get('limit', 100)) + METRICS.info( + "Projects", + extra={ + "user": request.user.username, + "sessionId": getattr(request.session, "session_key", ""), + "operation": "projects.listing", + "agent": request.META.get("HTTP_USER_AGENT"), + "ip": get_client_ip(request), + "info": {}, + }, + ) + listing = [] if query_string: @@ -108,7 +122,19 @@ def post(self, request): # pylint: disable=no-self-use title = data['title'] client = request.user.tapis_oauth.client - system_id = create_shared_workspace(client, title, request.user.username) + system_id = create_shared_workspace(client, title, request.user.username, tapis_tracking_id=f"portals.{request.session.session_key}") + + METRICS.info( + "Projects", + extra={ + "user": request.user.username, + "sessionId": getattr(request.session, "session_key", ""), + "operation": "projects.create", + "agent": request.META.get("HTTP_USER_AGENT"), + "ip": get_client_ip(request), + "info": {"body": data, "id": system_id}, + }, + ) return JsonResponse( { @@ -141,6 +167,18 @@ def get(self, request, project_id=None, system_id=None): if system_id is not None: project_id = system_id.split(f"{settings.PORTAL_PROJECTS_SYSTEM_PREFIX}.")[1] + METRICS.info( + "Projects", + extra={ + "user": request.user.username, + "sessionId": getattr(request.session, "session_key", ""), + "operation": "projects.detail", + "agent": request.META.get("HTTP_USER_AGENT"), + "ip": get_client_ip(request), + "info": {"project_id": project_id}, + }, + ) + prj = get_project(request.user.tapis_oauth.client, project_id) return JsonResponse( @@ -184,6 +222,18 @@ def patch( """ data = json.loads(request.body) + METRICS.info( + "Projects", + extra={ + "user": request.user.username, + "sessionId": getattr(request.session, "session_key", ""), + "operation": "projects.patch", + "agent": request.META.get("HTTP_USER_AGENT"), + "ip": get_client_ip(request), + "info": {"body": data}, + }, + ) + client = request.user.tapis_oauth.client workspace_def = update_project(client, project_id, data['title'], data['description']) return JsonResponse( @@ -219,6 +269,19 @@ def patch(self, request, project_id): 403, request.POST.dict() ) + + METRICS.info( + "Projects", + extra={ + "user": request.user.username, + "sessionId": getattr(request.session, "session_key", ""), + "operation": "projects.patchMembers", + "agent": request.META.get("HTTP_USER_AGENT"), + "ip": get_client_ip(request), + "info": {"body": data}, + }, + ) + return operation(request, project_id, **data) def transfer_ownership(self, request, project_id, **data): @@ -310,6 +373,19 @@ def change_system_role(self, request, project_Id, **data): def get_project_role(request, project_id, username): role = None client = request.user.tapis_oauth.client + + METRICS.info( + "Projects", + extra={ + "user": request.user.username, + "sessionId": getattr(request.session, "session_key", ""), + "operation": "projects.get_project_role", + "agent": request.META.get("HTTP_USER_AGENT"), + "ip": get_client_ip(request), + "info": {"project_id": project_id, "username": username}, + }, + ) + role = get_workspace_role(client, project_id, username) return JsonResponse({'username': username, 'role': role}) @@ -318,6 +394,19 @@ def get_project_role(request, project_id, username): @login_required def get_system_role(request, project_id, username): client = request.user.tapis_oauth.client + + METRICS.info( + "Projects", + extra={ + "user": request.user.username, + "sessionId": getattr(request.session, "session_key", ""), + "operation": "projects.get_system_role", + "agent": request.META.get("HTTP_USER_AGENT"), + "ip": get_client_ip(request), + "info": {"project_id": project_id, "username": username}, + }, + ) + role = get_workspace_role(client, project_id, username) return JsonResponse({'username': username, 'role': role}) diff --git a/server/portal/apps/projects/views_unit_test.py b/server/portal/apps/projects/views_unit_test.py index c47b38e41..ea28fe36e 100644 --- a/server/portal/apps/projects/views_unit_test.py +++ b/server/portal/apps/projects/views_unit_test.py @@ -198,7 +198,8 @@ def test_projects_post( # 2. service account client sets client.files.setFacl # 3. standard client creates workspace client.systems.createSystem mock_service_account().files.mkdir.assert_called_with( - systemId="projects.system.name", path="test.project-2" + systemId="projects.system.name", path="test.project-2", + headers={"X-Tapis-Tracking-ID": f"portals.{client.session.session_key}"} ) mock_service_account().files.setFacl.assert_called_with( systemId="projects.system.name", @@ -237,7 +238,8 @@ def test_projects_post_setfacl_job( # 2. service account client sets client.files.setFacl # 3. standard client creates workspace client.systems.createSystem mock_service_account().files.mkdir.assert_called_with( - systemId="projects.system.name", path="test.project-2" + systemId="projects.system.name", path="test.project-2", + headers={"X-Tapis-Tracking-ID": f"portals.{client.session.session_key}"} ) mock_service_account().files.setFacl.assert_not_called() mock_service_account().jobs.submitJob.assert_called_with( diff --git a/server/portal/apps/projects/workspace_operations/shared_workspace_operations.py b/server/portal/apps/projects/workspace_operations/shared_workspace_operations.py index 3bdd0c62c..79872732c 100644 --- a/server/portal/apps/projects/workspace_operations/shared_workspace_operations.py +++ b/server/portal/apps/projects/workspace_operations/shared_workspace_operations.py @@ -110,11 +110,13 @@ def submit_workspace_acls_job( return res -def create_workspace_dir(workspace_id: str) -> str: +def create_workspace_dir(workspace_id: str, **kwargs) -> str: client = service_account() system_id = settings.PORTAL_PROJECTS_ROOT_SYSTEM_NAME path = f"{workspace_id}" - client.files.mkdir(systemId=system_id, path=path) + client.files.mkdir(systemId=system_id, + path=path, + headers={"X-Tapis-Tracking-ID": kwargs.get("tapis_tracking_id", "")}) return path @@ -161,7 +163,7 @@ def increment_workspace_count(force=None) -> int: ########################################## -def create_shared_workspace(client: Tapis, title: str, owner: str): +def create_shared_workspace(client: Tapis, title: str, owner: str, **kwargs): """ Create a workspace system owned by user whose client is passed. """ @@ -170,7 +172,7 @@ def create_shared_workspace(client: Tapis, title: str, owner: str): workspace_id = f"{settings.PORTAL_PROJECTS_ID_PREFIX}-{workspace_number}" # Service client creates directory and gives owner write permissions - create_workspace_dir(workspace_id) + create_workspace_dir(workspace_id, **kwargs) set_workspace_acls(service_client, settings.PORTAL_PROJECTS_ROOT_SYSTEM_NAME, workspace_id, diff --git a/server/portal/apps/workspace/api/unit_test.py b/server/portal/apps/workspace/api/unit_test.py index 1ba9f0fd2..43d8b0ff9 100644 --- a/server/portal/apps/workspace/api/unit_test.py +++ b/server/portal/apps/workspace/api/unit_test.py @@ -21,7 +21,12 @@ def test_job_history_get(self): job_uuid = "032142c3-ac6a-42cb-841e-fbc26a2d951c-007" self.mock_tapis_client.jobs.getJobHistory.return_value = "mock_response" response = self.client.get("/api/workspace/jobs/{}/history".format(job_uuid)) - self.mock_tapis_client.jobs.getJobHistory.assert_called_with(jobUuid=job_uuid) + self.mock_tapis_client.jobs.getJobHistory.assert_called_with( + jobUuid=job_uuid, + headers={ + "X-Tapis-Tracking-ID": f"portals.{self.client.session.session_key}" + }, + ) data = json.loads(response.content) self.assertEqual(data, {"status": 200, "response": "mock_response"}) diff --git a/server/portal/apps/workspace/api/views.py b/server/portal/apps/workspace/api/views.py index a55fde210..2205c0856 100644 --- a/server/portal/apps/workspace/api/views.py +++ b/server/portal/apps/workspace/api/views.py @@ -11,6 +11,7 @@ from django.urls import reverse from django.db.models.functions import Coalesce from django.core.exceptions import PermissionDenied +from tapipy.tapis import TapisResult from tapipy.errors import InternalServerError, UnauthorizedError from portal.views.base import BaseApiView from portal.exceptions.api import ApiException @@ -27,6 +28,8 @@ check_job_for_timeout, test_system_credentials, ) +from portal.utils import get_client_ip + logger = logging.getLogger(__name__) METRICS = logging.getLogger('metrics.{}'.format(__name__)) @@ -90,8 +93,18 @@ def get(self, request, *args, **kwargs): tapis = request.user.tapis_oauth.client app_id = request.GET.get('appId') if app_id: + METRICS.info( + "Apps", + extra={ + "user": request.user.username, + "sessionId": getattr(request.session, "session_key", ""), + "operation": "getApp", + "agent": request.META.get("HTTP_USER_AGENT"), + "ip": get_client_ip(request), + "info": {"query": request.GET.dict()}, + }, + ) app_version = request.GET.get('appVersion') - METRICS.info("user:{} is requesting app id:{} version:{}".format(request.user.username, app_id, app_version)) data = _get_app(app_id, app_version, request.user) # Check if default storage system needs keys pushed @@ -106,7 +119,17 @@ def get(self, request, *args, **kwargs): data['systemNeedsKeys'] = not success data['pushKeysSystem'] = system_def else: - METRICS.info("user:{} is requesting all apps".format(request.user.username)) + METRICS.info( + "Apps", + extra={ + "user": request.user.username, + "sessionId": getattr(request.session, "session_key", ""), + "operation": "getApps", + "agent": request.META.get("HTTP_USER_AGENT"), + "ip": get_client_ip(request), + "info": {"query": request.GET.dict()}, + }, + ) data = {'appListing': tapis.apps.getApps()} return JsonResponse( @@ -143,6 +166,18 @@ def get(self, request, operation=None): if operation not in allowed_actions: raise PermissionDenied + METRICS.info( + "Jobs", + extra={ + "user": request.user.username, + "sessionId": getattr(request.session, "session_key", ""), + "operation": operation, + "agent": request.META.get("HTTP_USER_AGENT"), + "ip": get_client_ip(request), + "info": {"query": request.GET.dict()}, + }, + ) + op = getattr(self, operation) data = op(tapis, request) @@ -162,7 +197,7 @@ def get(self, request, operation=None): def select(self, client, request): job_uuid = request.GET.get('job_uuid') - data = client.jobs.getJob(jobUuid=job_uuid) + data = client.jobs.getJob(jobUuid=job_uuid, headers={"X-Tapis-Tracking-ID": f"portals.{request.session.session_key}"}) return data @@ -176,7 +211,7 @@ def listing(self, client, request): skip=offset, orderBy='lastUpdated(desc),name(asc)', _tapis_query_parameters={'tags.contains': f'portalName: {portal_name}'}, - select='allAttributes' + select='allAttributes', headers={"X-Tapis-Tracking-ID": f"portals.{request.session.session_key}"} ) return data @@ -209,15 +244,25 @@ def search(self, client, request): request_body={ "search": sql_queries }, - select="allAttributes" + select="allAttributes", headers={"X-Tapis-Tracking-ID": f"portals.{request.session.session_key}"} ) return data def delete(self, request, *args, **kwargs): + METRICS.info( + "Jobs", + extra={ + "user": request.user.username, + "sessionId": getattr(request.session, "session_key", ""), + "operation": "delete", + "agent": request.META.get("HTTP_USER_AGENT"), + "ip": get_client_ip(request), + "info": {"query": request.GET.dict()}, + }, + ) tapis = request.user.tapis_oauth.client job_uuid = request.GET.get('job_uuid') - METRICS.info("user:{} is deleting job uuid:{}".format(request.user.username, job_uuid)) - data = tapis.jobs.hideJob(jobUuid=job_uuid) + data = tapis.jobs.hideJob(jobUuid=job_uuid, headers={"X-Tapis-Tracking-ID": f"portals.{request.session.session_key}"}) return JsonResponse( { 'status': 200, @@ -237,11 +282,47 @@ def post(self, request, *args, **kwargs): if job_uuid and job_action: if job_action == 'resubmit': METRICS.info("user:{} is resubmitting job uuid:{}".format(username, job_uuid)) - data = tapis.jobs.resubmitJob(jobUuid=job_uuid) + data = tapis.jobs.resubmitJob(jobUuid=job_uuid, headers={"X-Tapis-Tracking-ID": f"portals.{request.session.session_key}"}) + if isinstance(data, TapisResult): + metrics_info = { + "body": body, + } + response_uuid = data.get("uuid", None) + if response_uuid: + metrics_info["response_uuid"] = response_uuid + METRICS.info( + "Jobs", + extra={ + "user": username, + "sessionId": getattr(request.session, "session_key", ""), + "operation": "resubmitJob", + "agent": request.META.get("HTTP_USER_AGENT"), + "ip": get_client_ip(request), + "info": metrics_info, + }, + ) elif job_action == 'cancel': METRICS.info("user:{} is canceling/stopping job uuid:{}".format(username, job_uuid)) - data = tapis.jobs.cancelJob(jobUuid=job_uuid) + data = tapis.jobs.cancelJob(jobUuid=job_uuid, headers={"X-Tapis-Tracking-ID": f"portals.{request.session.session_key}"}) + if isinstance(data, TapisResult): + metrics_info = { + "body": body, + } + response_uuid = data.get("uuid", None) + if response_uuid: + metrics_info["response_uuid"] = response_uuid + METRICS.info( + "Jobs", + extra={ + "user": username, + "sessionId": getattr(request.session, "session_key", ""), + "operation": "cancelJob", + "agent": request.META.get("HTTP_USER_AGENT"), + "ip": get_client_ip(request), + "info": metrics_info, + }, + ) else: raise ApiException("user:{} is trying to run an unsupported job action: {} for job uuid: {}".format( username, @@ -356,7 +437,27 @@ def post(self, request, *args, **kwargs): ] logger.info("user:{} is submitting job:{}".format(username, job_post)) - response = tapis.jobs.submitJob(**job_post) + response = tapis.jobs.submitJob(**job_post, headers={"X-Tapis-Tracking-ID": f"portals.{request.session.session_key}"}) + + if isinstance(response, TapisResult): + metrics_info = { + "body": body, + } + response_uuid = response.get("uuid", None) + if response_uuid: + metrics_info["response_uuid"] = response_uuid + METRICS.info( + "Jobs", + extra={ + "user": username, + "sessionId": getattr(request.session, "session_key", ""), + "operation": "submitJob", + "agent": request.META.get("HTTP_USER_AGENT"), + "ip": get_client_ip(request), + "info": metrics_info, + }, + ) + return JsonResponse( { 'status': 200, @@ -401,7 +502,7 @@ def post(self, request, *args, **kwargs): class JobHistoryView(BaseApiView): def get(self, request, job_uuid): tapis = request.user.tapis_oauth.client - data = tapis.jobs.getJobHistory(jobUuid=job_uuid) + data = tapis.jobs.getJobHistory(jobUuid=job_uuid, headers={"X-Tapis-Tracking-ID": f"portals.{request.session.session_key}"}) return JsonResponse( { 'status': 200, diff --git a/server/portal/apps/workspace/api/views_unit_test.py b/server/portal/apps/workspace/api/views_unit_test.py index e0923fd78..08fbc0da2 100644 --- a/server/portal/apps/workspace/api/views_unit_test.py +++ b/server/portal/apps/workspace/api/views_unit_test.py @@ -1,5 +1,5 @@ from django.conf import settings -from portal.apps.workspace.api.views import JobsView, AppsTrayView, AppsView +from portal.apps.workspace.api.views import AppsTrayView from portal.apps.workspace.models import AppTrayCategory from portal.apps.workspace.models import JobSubmission import json @@ -198,32 +198,30 @@ def test_job_post_is_logged_for_metrics( ) -def request_jobs_util(rf, authenticated_user, query_params={}): - # Unit test helper function - view = JobsView() - request = rf.get("/api/workspace/jobs/", query_params) - request.user = authenticated_user - operation = "listing" - response = view.get(request, operation) - return json.loads(response.content)["response"] +def request_jobs_util(client, authenticated_user, query_params={}): + response = client.get( + "/api/workspace/jobs/listing", + query_params, + ) + return response.json()["response"] -def test_get_no_tapis_jobs(rf, authenticated_user, mock_tapis_client): +def test_get_no_tapis_jobs(client, authenticated_user, mock_tapis_client): mock_tapis_client.jobs.getJobSearchList.return_value = [] - jobs = request_jobs_util(rf, authenticated_user) + jobs = request_jobs_util(client, authenticated_user) assert len(jobs) == 0 -def test_get_no_portal_jobs(rf, authenticated_user, mock_tapis_client): +def test_get_no_portal_jobs(client, authenticated_user, mock_tapis_client): JobSubmission.objects.create(user=authenticated_user, jobId="9876") mock_tapis_client.jobs.getJobSearchList.return_value = [] - jobs = request_jobs_util(rf, authenticated_user) + jobs = request_jobs_util(client, authenticated_user) assert len(jobs) == 0 -def test_get_jobs_bad_offset(rf, authenticated_user, mock_tapis_client): +def test_get_jobs_bad_offset(client, authenticated_user, mock_tapis_client): mock_tapis_client.jobs.getJobSearchList.return_value = [] - jobs = request_jobs_util(rf, authenticated_user, query_params={"offset": 100}) + jobs = request_jobs_util(client, authenticated_user, query_params={"offset": 100}) assert len(jobs) == 0 @@ -280,7 +278,7 @@ def test_get_app_dynamic_exec_sys( django_db_blocker, mock_tapis_client, authenticated_user, - rf, + client, tapis_get_systems_list, ): # Load fixtures @@ -299,13 +297,10 @@ def test_get_app_dynamic_exec_sys( else: mock_tapis_client.systems.getSystem.return_value = tapis_get_systems_list[1] # invoke and assert - apps_view = AppsView() query_params = {"appId": "hello-world", "appVersion": "0.0.1"} - request = rf.get("/api/workspace/apps/", query_params) - request.user = authenticated_user - response = apps_view.get(request) + response = client.get("/api/workspace/apps/", query_params) assert response.status_code == 200 - response_json = json.loads(response.content)["response"] + response_json = response.json()["response"] assert response_json["definition"]["id"] == "hello-world" assert response_json["definition"]["version"] == "0.0.1" if dynamic_exec_system: diff --git a/server/portal/apps/workspace/tasks.py b/server/portal/apps/workspace/tasks.py deleted file mode 100644 index 796397725..000000000 --- a/server/portal/apps/workspace/tasks.py +++ /dev/null @@ -1,54 +0,0 @@ -from django.contrib.auth import get_user_model -from requests import ConnectionError, HTTPError -import logging - -logger = logging.getLogger(__name__) - - -class JobSubmitError(Exception): - - def __init__(self, *args, **kwargs): - self.status = kwargs.pop('status', 'error') - self.status_code = kwargs.pop('status_code', 500) - self.message = kwargs.pop('message', None) - - def json(self): - return { - 'status': getattr(self, 'status', 'error'), - 'message': getattr(self, 'message', None) - } - - -def submit_job(request, username, job_post): - logger.info('Submitting job for user=%s: %s' % (username, job_post)) - - try: - user = get_user_model().objects.get(username=username) - agave = user.tapis_oauth.client - response = agave.jobs.submit(body=job_post) - logger.debug('Job Submission Response: {}'.format(response)) - - return response - - except ConnectionError as e: - logger.error('ConnectionError while submitting job: %s' % e, - extra={'job': job_post}) - raise JobSubmitError(status='error', - status_code=500, - message='We were unable to submit your job at this time due ' - 'to a Job Service Interruption. Please try again later.') - - except HTTPError as e: - logger.error('HTTPError while submitting job: %s' % e, - extra={'job': job_post}) - if e.response.status_code >= 500: - raise JobSubmitError( - status='error', - status_code=e.response.status_code, - message='We were unable to submit your job at this time due ' - 'to a Job Service Interruption. Please try again later.') - - err_resp = e.response.json() - err_resp['status_code'] = e.response.status_code - logger.warning(err_resp) - raise JobSubmitError(**err_resp) diff --git a/server/portal/libs/agave/operations.py b/server/portal/libs/agave/operations.py index 83264a1a8..c45c2a080 100644 --- a/server/portal/libs/agave/operations.py +++ b/server/portal/libs/agave/operations.py @@ -40,7 +40,8 @@ def listing(client, system, path, offset=0, limit=100, *args, **kwargs): raw_listing = client.files.listFiles(systemId=system, path=path, offset=int(offset), - limit=int(limit)) + limit=int(limit), + headers={"X-Tapis-Tracking-ID": kwargs.get("tapis_tracking_id", "")}) try: # Convert file objects to dicts for serialization. @@ -176,7 +177,7 @@ def download(client, system, path, max_uses=3, lifetime=600, **kwargs): return redeemUrl -def mkdir(client, system, path, dir_name): +def mkdir(client, system, path, dir_name, **kwargs): """Create a new directory. Params @@ -207,7 +208,7 @@ def mkdir(client, system, path, dir_name): return {"result": "OK"} -def move(client, src_system, src_path, dest_system, dest_path, file_name=None): +def move(client, src_system, src_path, dest_system, dest_path, file_name=None, **kwargs): """Move a current file to the given destination. Params @@ -251,7 +252,8 @@ def move(client, src_system, src_path, dest_system, dest_path, file_name=None): move_result = client.files.moveCopy(systemId=src_system, path=src_path, operation="MOVE", - newPath=dest_path_full) + newPath=dest_path_full, + headers={"X-Tapis-Tracking-ID": kwargs.get("tapis_tracking_id", "")}) if os.path.dirname(src_path) != dest_path or src_path != dest_path: tapis_indexer.apply_async(kwargs={'access_token': client.access_token.access_token, @@ -318,7 +320,8 @@ def copy(client, src_system, src_path, dest_system, dest_path, file_name=None, copy_result = client.files.moveCopy(systemId=src_system, path=src_path, operation="COPY", - newPath=dest_path_full) + newPath=dest_path_full, + headers={"X-Tapis-Tracking-ID": kwargs.get("tapis_tracking_id", "")}) else: src_url = f'tapis://{src_system}/{src_path}' @@ -327,7 +330,7 @@ def copy(client, src_system, src_path, dest_system, dest_path, file_name=None, copy_response = client.files.createTransferTask(elements=[{ 'sourceURI': src_url, 'destinationURI': dest_url - }]) + }], headers={"X-Tapis-Tracking-ID": kwargs.get("tapis_tracking_id", "")}) copy_result = { 'uuid': copy_response.uuid, @@ -364,12 +367,13 @@ def makepublic(client, src_system, src_path, dest_path='/', *args, **kwargs): *args, **kwargs) -def delete(client, system, path): +def delete(client, system, path, *args, **kwargs): return client.files.delete(systemId=system, - path=path) + path=path, + headers={"X-Tapis-Tracking-ID": kwargs.get("tapis_tracking_id", "")}) -def rename(client, system, path, new_name): +def rename(client, system, path, new_name, *args, **kwargs): """Renames a file. This is performed under the hood by moving the file to the same parent folder but with a new name. @@ -390,10 +394,10 @@ def rename(client, system, path, new_name): """ new_path = os.path.dirname(path) return move(client, src_system=system, src_path=path, - dest_system=system, dest_path=new_path, file_name=new_name) + dest_system=system, dest_path=new_path, file_name=new_name, **kwargs) -def trash(client, system, path, homeDir): +def trash(client, system, path, homeDir, *args, **kwargs): """Move a file to the .Trash folder. Params @@ -423,12 +427,12 @@ def trash(client, system, path, homeDir): mkdir(client, system, homeDir, settings.TAPIS_DEFAULT_TRASH_NAME) resp = move(client, system, path, system, - f'{homeDir}/{settings.TAPIS_DEFAULT_TRASH_NAME}', file_name) + f'{homeDir}/{settings.TAPIS_DEFAULT_TRASH_NAME}', file_name, **kwargs) return resp -def upload(client, system, path, uploaded_file): +def upload(client, system, path, uploaded_file, *args, **kwargs): """Upload a file. Params ------ @@ -449,7 +453,10 @@ def upload(client, system, path, uploaded_file): uploaded_file.name = increment_file_name(listing=file_listing, file_name=uploaded_file.name) dest_path = os.path.join(path.strip('/'), uploaded_file.name) - response_json = client.files.insert(systemId=system, path=dest_path, file=uploaded_file) + response_json = client.files.insert(systemId=system, + path=dest_path, + file=uploaded_file, + headers={"X-Tapis-Tracking-ID": kwargs.get("tapis_tracking_id", "")}) tapis_indexer.apply_async(kwargs={'access_token': client.access_token.access_token, 'systemId': system, 'filePath': path, @@ -482,7 +489,10 @@ def preview(client, system, path, max_uses=3, lifetime=600, **kwargs): file_name = path.strip('/').split('/')[-1] file_ext = os.path.splitext(file_name)[1].lower() - postit = client.files.createPostIt(systemId=system, path=path, allowedUses=max_uses, validSeconds=lifetime) + postit = client.files.createPostIt(systemId=system, + path=path, allowedUses=max_uses, + validSeconds=lifetime, + headers={"X-Tapis-Tracking-ID": kwargs.get("tapis_tracking_id", "")}) url = postit.redeemUrl txt = None @@ -521,7 +531,7 @@ def preview(client, system, path, max_uses=3, lifetime=600, **kwargs): return {'href': url, 'fileType': file_type, 'content': txt, 'error': error} -def download_bytes(client, system, path): +def download_bytes(client, system, path, *args, **kwargs): """Returns a BytesIO object representing the file. Params diff --git a/server/portal/libs/agave/operations_unit_test.py b/server/portal/libs/agave/operations_unit_test.py index 81ddfaa85..b4049fd14 100644 --- a/server/portal/libs/agave/operations_unit_test.py +++ b/server/portal/libs/agave/operations_unit_test.py @@ -28,7 +28,8 @@ def test_listing(self, mock_indexer): client.files.listFiles.assert_called_with(systemId='test.system', path='/path/to/file', offset=1, - limit=100) + limit=100, + headers={'X-Tapis-Tracking-ID': ''}) mock_response_listing = [{'system': 'test.system', 'type': 'file', @@ -112,7 +113,11 @@ def test_move(self, mock_indexer): move(client, 'test.system', '/path/to/src', 'test.system', '/path/to/dest') - client.files.moveCopy.assert_called_with(systemId='test.system', path='/path/to/src', operation='MOVE', newPath='path/to/dest/src') + client.files.moveCopy.assert_called_with(systemId='test.system', + path='/path/to/src', + operation='MOVE', + newPath='path/to/dest/src', + headers={'X-Tapis-Tracking-ID': ''}) self.assertEqual(mock_indexer.apply_async.call_count, 3) @@ -128,7 +133,11 @@ def test_copy(self, mock_indexer): copy(client, 'test.system', '/path/to/src', 'test.system', '/path/to/dest') - client.files.moveCopy.assert_called_with(systemId='test.system', path='/path/to/src', operation='COPY', newPath='path/to/dest/src') + client.files.moveCopy.assert_called_with(systemId='test.system', + path='/path/to/src', + operation='COPY', + newPath='path/to/dest/src', + headers={'X-Tapis-Tracking-ID': ''}) self.assertEqual(mock_indexer.apply_async.call_count, 2) diff --git a/server/portal/settings/settings.py b/server/portal/settings/settings.py index 1321974d1..09d7ef2d2 100644 --- a/server/portal/settings/settings.py +++ b/server/portal/settings/settings.py @@ -11,6 +11,7 @@ """ import os +import uuid import logging from kombu import Exchange, Queue from portal.settings import settings_secret @@ -289,9 +290,25 @@ SETTINGS: LOGGING """ + +def portal_filter(record): + """Log filter that adds portal-specific vars to each entry""" + + record.logGuid = uuid.uuid4().hex + record.portal = PORTAL_NAMESPACE + record.tenant = TAPIS_TENANT_BASEURL + return True + + LOGGING = { 'version': 1, 'disable_existing_loggers': False, + "filters": { + "portalFilter": { + "()": "django.utils.log.CallbackFilter", + "callback": portal_filter, + }, + }, 'formatters': { 'default': { 'format': '[DJANGO] %(levelname)s %(asctime)s UTC %(module)s ' @@ -302,8 +319,9 @@ '%(name)s.%(funcName)s:%(lineno)s: %(message)s' }, 'metrics': { - 'format': '[METRICS] %(levelname)s %(asctime)s UTC %(module)s ' - '%(name)s.%(funcName)s:%(lineno)s: %(message)s' + 'format': '[METRICS] %(levelname)s %(module)s %(name)s.%(funcName)s:%(lineno)s:' + ' %(message)s user=%(user)s ip=%(ip)s agent=%(agent)s sessionId=%(sessionId)s op=%(operation)s' + ' info=%(info)s timestamp=%(asctime)s trackingId=portals.%(sessionId)s guid=%(logGuid)s portal=%(portal)s tenant=%(tenant)s' }, }, 'handlers': { @@ -320,18 +338,11 @@ 'backupCount': 5, 'formatter': 'default', }, - 'metrics_console': { - 'level': 'DEBUG', + 'metrics': { + 'level': 'INFO', 'class': 'logging.StreamHandler', 'formatter': 'metrics', - }, - 'metrics_file': { - 'level': 'DEBUG', - 'class': 'logging.handlers.RotatingFileHandler', - 'filename': '/var/log/portal/metrics.log', - 'maxBytes': 1024*1024*5, # 5 MB - 'backupCount': 5, - 'formatter': 'metrics', + 'filters': ['portalFilter'] }, }, 'loggers': { @@ -345,8 +356,9 @@ 'level': 'DEBUG', }, 'metrics': { - 'handlers': ['metrics_console', 'metrics_file'], - 'level': 'DEBUG', + 'handlers': ['metrics'], + 'filters': ['portalFilter'], + 'level': 'INFO', }, 'paramiko': { 'handlers': ['console'], diff --git a/server/portal/utils/__init__.py b/server/portal/utils/__init__.py index e69de29bb..4110a1de2 100644 --- a/server/portal/utils/__init__.py +++ b/server/portal/utils/__init__.py @@ -0,0 +1,11 @@ +"""Utils for use across multiple apps""" + + +def get_client_ip(request): + """Extract an IP address from a Django request object.""" + x_forwarded_for = request.META.get("HTTP_X_FORWARDED_FOR") + if x_forwarded_for: + ip = x_forwarded_for.split(",")[-1].strip() + else: + ip = request.META.get("REMOTE_ADDR") + return ip