Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Bug/WI-67: Logging and forcing tapis token retrieval on every request #6

Closed
wants to merge 1 commit into from

Conversation

chandra-tacc
Copy link
Contributor

Overview

  • There is a security hole right now, where a user can find the upstream path and directly access a cached version of report.
  • There is no logging for inbound and outbound requests from datastore.

Fixes

  • Check for tapis token access for all requests, even for ones looking at cached report data. This is secure data, having access to tapis token is needed to look at the same cached data.
  • Logging:
    • Log all requests - incoming and outgoing
    • Log anything added to cache.

Testing

Test Results

Note: in test results, the exception handling messages are different based on how the report was authored. It is out of scope of the WMA to adjust report logic.

2023-11-01 15:25:20 +0000] [1] [INFO] Starting gunicorn 20.1.0
[2023-11-01 15:25:20 +0000] [1] [INFO] Listening at: http://0.0.0.0:8050 (1)
[2023-11-01 15:25:20 +0000] [1] [INFO] Using worker: sync
[2023-11-01 15:25:20 +0000] [14] [INFO] Booting worker with pid: 14


[2023-11-01 15:26:56 +0000] [14] [INFO] 10.244.6.116 "GET http://a2cps-datastore-latest:8050/api/imaging"
[2023-11-01 15:26:56 +0000] [14] [INFO] Received tapis token.
[2023-11-01 15:26:56 +0000] [14] [INFO] Sending request to https://a2cps.tapis.io/v3/files/content/secure.corral/corral-secure/projects/A2CPS/community/reports//imaging/imaging-log-latest.csv
[2023-11-01 15:26:57 +0000] [14] [INFO] Response status code: 200
[2023-11-01 15:26:57 +0000] [14] [INFO] Sending request to https://a2cps.tapis.io/v3/files/content/secure.corral/corral-secure/projects/A2CPS/community/reports//imaging/qc-log-latest.csv
[2023-11-01 15:26:57 +0000] [14] [INFO] Response status code: 200
[2023-11-01 15:26:57 +0000] [14] [INFO] Caching imaging report data. Date: 11/01/2023, 15:26:56
[2023-11-01 15:26:58 +0000] [14] [INFO] 10.244.6.116 "GET http://a2cps-datastore-latest:8050/api/imaging" 200
[2023-11-01 15:27:17 +0000] [14] [INFO] 10.244.3.185 "GET http://a2cps-datastore-latest:8050/api/subjects"
[2023-11-01 15:27:17 +0000] [14] [INFO] Received tapis token.
[2023-11-01 15:27:17 +0000] [14] [INFO] Sending request to https://a2cps.tapis.io/v3/files/content/secure.corral/corral-secure/projects/A2CPS/community/reports//subjects/subjects-1-latest.json
[2023-11-01 15:27:17 +0000] [14] [INFO] Response status code: 200
[2023-11-01 15:27:17 +0000] [14] [INFO] Sending request to https://a2cps.tapis.io/v3/files/content/secure.corral/corral-secure/projects/A2CPS/community/reports//subjects/subjects-2-latest.json
[2023-11-01 15:27:18 +0000] [14] [INFO] Response status code: 200
[2023-11-01 15:27:20 +0000] [14] [INFO] Caching subjects api response data. Date: 11/01/2023, 15:27:17
[2023-11-01 15:27:21 +0000] [14] [INFO] 10.244.3.185 "GET http://a2cps-datastore-latest:8050/api/subjects" 200
[2023-11-01 15:27:45 +0000] [14] [INFO] 10.244.11.198 "GET http://a2cps-datastore-latest:8050/api/subjects"
[2023-11-01 15:27:45 +0000] [14] [INFO] Received tapis token.
[2023-11-01 15:27:47 +0000] [14] [INFO] 10.244.11.198 "GET http://a2cps-datastore-latest:8050/api/subjects" 200
[2023-11-01 15:28:26 +0000] [14] [INFO] 10.244.7.249 "GET http://a2cps-datastore-latest:8050/api/consort"
[2023-11-01 15:28:27 +0000] [14] [INFO] Received tapis token.
[2023-11-01 15:28:27 +0000] [14] [INFO] Sending request to https://a2cps.tapis.io/v3/files/content/secure.corral/corral-secure/projects/A2CPS/community/reports//consort/consort-data-1-latest.csv
[2023-11-01 15:28:27 +0000] [14] [INFO] Response status code: 200
[2023-11-01 15:28:27 +0000] [14] [INFO] Sending request to https://a2cps.tapis.io/v3/files/content/secure.corral/corral-secure/projects/A2CPS/community/reports//consort/consort-data-2-latest.csv
[2023-11-01 15:28:27 +0000] [14] [INFO] Response status code: 200
[2023-11-01 15:28:27 +0000] [14] [INFO] Caching consort report data. Date: 11/01/2023, 15:28:27
[2023-11-01 15:28:27 +0000] [14] [INFO] 10.244.7.249 "GET http://a2cps-datastore-latest:8050/api/consort" 200
[2023-11-01 15:59:18 +0000] [14] [INFO] 10.244.6.116 "GET http://a2cps-datastore-latest:8050/api/imaging"
[2023-11-01 15:59:18 +0000] [14] [ERROR] Error in imaging API request: Missing session id
[2023-11-01 15:59:18 +0000] [14] [INFO] 10.244.6.116 "GET http://a2cps-datastore-latest:8050/api/imaging" 200
[2023-11-01 15:59:36 +0000] [14] [INFO] 10.244.7.249 "GET http://a2cps-datastore-latest:8050/api/consort"
[2023-11-01 15:59:36 +0000] [14] [ERROR] Error handling request /api/consort
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/gunicorn/workers/sync.py", line 136, in handle
    self.handle_request(listener, req, client, addr)
  File "/usr/local/lib/python3.9/site-packages/gunicorn/workers/sync.py", line 179, in handle_request
    respiter = self.wsgi(environ, resp.start_response)
  File "/usr/local/lib/python3.9/site-packages/flask/app.py", line 2091, in __call__
    return self.wsgi_app(environ, start_response)
  File "/usr/local/lib/python3.9/site-packages/flask/app.py", line 2076, in wsgi_app
    response = self.handle_exception(e)
  File "/usr/local/lib/python3.9/site-packages/flask/app.py", line 2073, in wsgi_app
    response = self.full_dispatch_request()
  File "/usr/local/lib/python3.9/site-packages/flask/app.py", line 1518, in full_dispatch_request
    rv = self.handle_user_exception(e)
  File "/usr/local/lib/python3.9/site-packages/flask/app.py", line 1516, in full_dispatch_request
    rv = self.dispatch_request()
  File "/usr/local/lib/python3.9/site-packages/flask/app.py", line 1502, in dispatch_request
    return self.ensure_sync(self.view_functions[rule.endpoint])(**req.view_args)
  File "/app/app.py", line 174, in api_consort
    tapis_token = get_tapis_token(request)
  File "/app/data_loading.py", line 398, in get_tapis_token
    raise Exception("Missing session id")
Exception: Missing session id
[2023-11-01 15:59:56 +0000] [14] [INFO] 10.244.3.185 "GET http://a2cps-datastore-latest:8050/api/subjects"
[2023-11-01 15:59:56 +0000] [14] [ERROR] Error in subjects API request: Missing session id
[2023-11-01 15:59:56 +0000] [14] [INFO] 10.244.3.185 "GET http://a2cps-datastore-latest:8050/api/subjects" 200

Copy link
Collaborator

@fnets fnets left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

name: Build on push to bug/WI-67-connection-issues
on:
push:
branches: [ bug/WI-67-connection-issues ]
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should we maybe abstract this and create a "experiment" branch that we push changes like this to, instead of creating workflows for each unusual case like this?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, I agree.


@app.before_request
def before_request_log():
app.logger.info(f"{request.remote_addr} \"{request.method} {request.url}\"")
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If the logging level is set to DEBUG shouldn't it be:

Suggested change
app.logger.info(f"{request.remote_addr} \"{request.method} {request.url}\"")
app.logger.debug(f"{request.remote_addr} \"{request.method} {request.url}\"")

If we just want this log at the info level and available all the time in the logs, I'm fine with that too.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Agree, will move it to DEBUG.


@app.after_request
def after_request_log(response):
app.logger.info(f"{request.remote_addr} \"{request.method} {request.url}\" {response.status_code}")
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
app.logger.info(f"{request.remote_addr} \"{request.method} {request.url}\" {response.status_code}")
app.logger.debug(f"{request.remote_addr} \"{request.method} {request.url}\" {response.status_code}")

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes.

@chandra-tacc chandra-tacc deleted the bug/WI-67-connection-issues branch November 2, 2023 18:58
@chandra-tacc
Copy link
Contributor Author

@fnets - renamed branch as experiment and created this PR: 7

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants