Audit Log should include Access Token created for AssumeRoleWith* requests

[anthu]

Is your feature request related to a problem? Please describe.
We are using the STS feature where programmatic clients are connecting by assuming a role using WebIdentity (AWS S3 v2 Client). From that point we can track this client using the logged Access Key.

Unfortunately we cannot correlate the Auditlog for the AssumeRoleWith* with the requests using this AccessToken.

Describe the solution you'd like
The Auditlog could be extended by an additional struct to provide information about the request beyond HTTP Headers.
This could also be used to eg. identify the exact 403 Reason in other APIs

Describe alternatives you've considered
Time based correlation was not helpful due to parallel processing on the same host not sharing the same AccessKey, but OpenID credentials.

Additional context
We are seeing 403 responses for requests made using STS tokens. These tokens have been generated on the same host as they have been used for eg. GetObject. The same token does work on a different host for the same Object. We can not trace the whole request chain, nor identify the exact "Forbidden" reason.

[timhughes]

I have just realised that this does work with AssumeRoleWithLDAPIdentity and i see something like

{
  "version": "1",
  "deploymentid": "d98222d1-af03-461d-a8f3-4b57ae296e04",
  "time": "2020-05-18T20:35:52.716266219Z",
  "api": {
    "name": "GetObject",
    "bucket": "disk2",
    "object": "tenant1/somedata.txt",
    "status": "OK",
    "statusCode": 200,
    "timeToFirstByte": "3.262021ms",
    "timeToResponse": "3.313487ms"
  },
  "remotehost": "::1",
  "requestID": "161039BCE0225B81",
  "userAgent": "aws-cli/1.18.62 Python/3.8.2 Linux/5.6.12-300.fc32.x86_64 botocore/1.16.12",
  "requestClaims": {
    "accessKey": "1X2T9RX2LJ1L3HYZM5BX",
    "exp": 1590049225,
    "ldapGroups": null,
    "ldapUser": "Philip J. Fry"
  },
  "lotsMoreJson": {
    "gone":"This section has been removed"
  }
}

[anthu]

Hey @timhughes
I think we're messing up different topics here.
I was referring to Audit logs regrading the API "AssumeRoleWith*". So something like

{
    "version": "1",
    "deploymentid": "a35f94a1-9a35-4e68-ba80-d57a3f8f4c74",
    "time": "2020-05-19T07:10:02.415737887Z",
    "api": {
        "name": "AssumeRoleWithWebIdentity",
        "status": "OK",
        "statusCode": 200,
        "timeToFirstByte": "207.100747ms",
        "timeToResponse": "207.14946ms"
    },
    "remotehost": "<redacted>",
    "requestID": "16105C582AE90501",
    "userAgent": "aws-sdk-java/2.11.6 Linux/3.10.0-1127.el7.x86_64 OpenJDK_64-Bit_Server_VM/11.0.7+10-LTS Java/11.0.7 vendor/Oracle_Corporation io/sync http/Apache",
    "requestHeader": {
        "Amz-Sdk-Invocation-Id": "035d9808-51fc-0622-1ceb-db1ce62feed4",
        "Amz-Sdk-Retry": "0/0/",
        "Content-Length": "1434",
        "Content-Type": "application/x-www-form-urlencoded; charset=utf-8",
        "User-Agent": "aws-sdk-java/2.11.6 Linux/3.10.0-1127.el7.x86_64 OpenJDK_64-Bit_Server_VM/11.0.7+10-LTS Java/11.0.7 vendor/Oracle_Corporation io/sync http/Apache",
        "X-Forwarded-For": "<redacted>"
    },
    "responseHeader": {
        "Accept-Ranges": "bytes",
        "Content-Length": "1776",
        "Content-Security-Policy": "block-all-mixed-content",
        "Content-Type": "application/xml",
        "ETag": "",
        "Server": "MinIO/RELEASE.2020-05-01T22-19-14Z",
        "Vary": "Origin",
        "X-Amz-Request-Id": "16105C582AE90501",
        "X-Xss-Protection": "1; mode=block"
    }
}

From this Audit Log I can not figure out what STS user has been created but looking at time and remotehost.

Decoded Bearer Token would be another Feature Request IMHO.

[anthu]

But an interesting thing in your shared Audit logs is the timeToFirstByte field in the first one. It shouldn't be at 0s 🤔

[vadmeste]

But an interesting thing in your shared Audit logs is the timeToFirstByte field in the first one. It shouldn't be at 0s

Yes, I am aware with this. I will need to talk with the team about this. I am not sure how to define time to first byte when the body does not contain any data, like a 204 HTTP response code.

[anthu]

But an interesting thing in your shared Audit logs is the timeToFirstByte field in the first one. It shouldn't be at 0s

Yes, I am aware with this. I will need to talk with the team about this. I am not sure how to define time to first byte when the body does not contain any data, like a 204 HTTP response code.

Haha - true 🤔
I'm not that familiar with Golang, but shouldn't the time to first byte be calculated on the first response byte of the header as provided here:
https://golang.org/pkg/net/http/httptrace/#ClientTrace

Thank you for looking into this and PR #9641 by your team removing the humanising - this will make profiling way easier

[timhughes]

@anthu Yeah i see what you mean. Similar but slightly different issue. I have raised another issue #9644 and moved some of my comments so as not to confuse the two.

This is start of the auditlog event with "timeToFirstByte":"0s", for reference

{
   "version":"1",
   "deploymentid":"d98222d1-af03-461d-a8f3-4b57ae296e04",
   "time":"2020-05-18T16:47:19.972956586Z",
   "api":{
      "name":"WebUpload",
      "bucket":"disk2",
      "object":"tenant2/somedata.txt",
      "status":"OK",
      "statusCode":200,
      "timeToFirstByte":"0s",
      "timeToResponse":"19.667509ms"
   },

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed after 15 days if no further activity occurs. Thank you for your contributions.

[harshavardhana]

A minor refactor is needed here, will send it coming week.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed after 15 days if no further activity occurs. Thank you for your contributions.