Log auth info on permission denied due to ACL #2754

bkrodgers · 2017-05-23T00:14:40Z

Test case (depends on jq for ease of reading, remove if you want):

bin/vault server -dev &
export VAULT_ADDR='http://127.0.0.1:8200'
vault audit-enable file file_path=/tmp/vault.log
vault write auth/token/roles/testrole allowed_policies=default
vault write /secret/test key=data
vault read /secret/test
vault write -field=token auth/token/create/testrole display_name=testuser > ~/.vault-token2 ; mv ~/.vault-token2 ~/.vault-token
vault read /secret/test
grep '"path":"secret/test"' /tmp/vault.log | grep '"operation":"read"' | jq

Result:

{
  "time": "2017-05-23T00:06:40Z",
  "type": "request",
  "auth": {
    "client_token": "",
    "accessor": "",
    "display_name": "root",
    "policies": [
      "root"
    ],
    "metadata": null
  },
  "request": {
    "id": "74c4ab04-cdc3-5856-3889-f0ae90f57870",
    "operation": "read",
    "client_token": "hmac-sha256:19621e2de54a9dcddc73bf2234dd46f4b642b26bf49cacbfbd08bdd3631f9e83",
    "client_token_accessor": "hmac-sha256:bef588d30ac2304f4cf9c95f0f5898eff8ad49de1fed86cec28b7027630ca9ab",
    "path": "secret/test",
    "data": null,
    "remote_address": "127.0.0.1",
    "wrap_ttl": 0,
    "headers": {}
  },
  "error": ""
}
{
  "time": "2017-05-23T00:06:40Z",
  "type": "response",
  "auth": {
    "client_token": "",
    "accessor": "",
    "display_name": "root",
    "policies": [
      "root"
    ],
    "metadata": null
  },
  "request": {
    "id": "74c4ab04-cdc3-5856-3889-f0ae90f57870",
    "operation": "read",
    "client_token": "hmac-sha256:19621e2de54a9dcddc73bf2234dd46f4b642b26bf49cacbfbd08bdd3631f9e83",
    "client_token_accessor": "hmac-sha256:bef588d30ac2304f4cf9c95f0f5898eff8ad49de1fed86cec28b7027630ca9ab",
    "path": "secret/test",
    "data": null,
    "remote_address": "127.0.0.1",
    "wrap_ttl": 0,
    "headers": {}
  },
  "response": {
    "secret": {
      "lease_id": ""
    },
    "data": {
      "key": "hmac-sha256:10f49bdcee36ad5411c601fce92429087a0ca10573f8d0e20b777a04c2b5377b"
    }
  },
  "error": ""
}
{
  "time": "2017-05-23T00:06:40Z",
  "type": "request",
  "auth": {
    "client_token": "",
    "accessor": "",
    "display_name": "token-testuser",
    "policies": [
      "default"
    ],
    "metadata": null
  },
  "request": {
    "id": "b9cfc344-22b1-d5b5-b55e-8fdd904275ca",
    "operation": "read",
    "client_token": "hmac-sha256:74cf7d28b98f8d09d7e4afad6d10d325a0861aa783db90ede7c7ec549733357d",
    "client_token_accessor": "hmac-sha256:40eb83f5c0fac9a9c5f85a9c8d9fc50a2b22a797636d528c0dadf5b83ad61e99",
    "path": "secret/test",
    "data": null,
    "remote_address": "127.0.0.1",
    "wrap_ttl": 0,
    "headers": {}
  },
  "error": "permission denied"
}
{
  "time": "2017-05-23T00:06:40Z",
  "type": "response",
  "auth": {
    "client_token": "",
    "accessor": "",
    "display_name": "token-testuser",
    "policies": [
      "default"
    ],
    "metadata": null
  },
  "request": {
    "id": "b9cfc344-22b1-d5b5-b55e-8fdd904275ca",
    "operation": "read",
    "client_token": "hmac-sha256:74cf7d28b98f8d09d7e4afad6d10d325a0861aa783db90ede7c7ec549733357d",
    "client_token_accessor": "hmac-sha256:40eb83f5c0fac9a9c5f85a9c8d9fc50a2b22a797636d528c0dadf5b83ad61e99",
    "path": "secret/test",
    "data": null,
    "remote_address": "127.0.0.1",
    "wrap_ttl": 0,
    "headers": {}
  },
  "response": {
    "data": {
      "error": "hmac-sha256:9893d3283db38b32de175ce1432b355002f17429c735005e6cd6137dbd30f681"
    }
  },
  "error": "1 error occurred:\n\n* permission denied"
}

Without this PR, the auth object for the second pair of req/resp would be missing info such as display name and policies that are important for determining who was denied access and why.

vishalnayak · 2017-05-23T14:49:59Z

vault/core.go

 	// Check the standard non-root ACLs. Return the token entry if it's not
 	// allowed so we can decrement the use count.
 	allowed, rootPrivs := acl.AllowOperation(req)
 	if !allowed {
-		return nil, te, logical.ErrPermissionDenied
+		return auth, te, logical.ErrPermissionDenied


Can we add a comment here explaining the need to return the auth object even when the operation is not allowed?

Sure. I've got another push coming to add populating the token and accessor fields in the auth object as well. (see latest comments on #2741) I'll include that in the push.

vishalnayak

LGTM!

bkrodgers · 2017-05-23T15:31:32Z

@vishalnayak Pushed your requested change along with changes to populate the ClientToken (hmac'd) and Accessor fields that were always blank before. Per the discussion on #2741, left the existing fields in the request object.

bkrodgers · 2017-05-23T15:33:55Z

New sample output with the latest change. Also populated metadata on my test token to show that gets logged as well:

Normal:

{
  "time": "2017-05-23T15:28:43Z",
  "type": "request",
  "auth": {
    "client_token": "hmac-sha256:c030cd973798da5b098545db766b73345a06e675a51883c12c98f80efd8a8eac",
    "accessor": "a591990d-8dc4-685d-8021-b73c0f338ea2",
    "display_name": "root",
    "policies": [
      "root"
    ],
    "metadata": null
  },
  "request": {
    "id": "950ae328-7942-8359-b85f-4a08c060d18f",
    "operation": "read",
    "client_token": "hmac-sha256:c030cd973798da5b098545db766b73345a06e675a51883c12c98f80efd8a8eac",
    "client_token_accessor": "a591990d-8dc4-685d-8021-b73c0f338ea2",
    "path": "secret/test",
    "data": null,
    "remote_address": "127.0.0.1",
    "wrap_ttl": 0,
    "headers": {}
  },
  "error": ""
}
{
  "time": "2017-05-23T15:28:43Z",
  "type": "response",
  "auth": {
    "client_token": "hmac-sha256:c030cd973798da5b098545db766b73345a06e675a51883c12c98f80efd8a8eac",
    "accessor": "a591990d-8dc4-685d-8021-b73c0f338ea2",
    "display_name": "root",
    "policies": [
      "root"
    ],
    "metadata": null
  },
  "request": {
    "id": "950ae328-7942-8359-b85f-4a08c060d18f",
    "operation": "read",
    "client_token": "hmac-sha256:c030cd973798da5b098545db766b73345a06e675a51883c12c98f80efd8a8eac",
    "client_token_accessor": "a591990d-8dc4-685d-8021-b73c0f338ea2",
    "path": "secret/test",
    "data": null,
    "remote_address": "127.0.0.1",
    "wrap_ttl": 0,
    "headers": {}
  },
  "response": {
    "secret": {
      "lease_id": ""
    },
    "data": {
      "key": "hmac-sha256:c8ac20d268007508a2146aeb37a87b8692dfbebf9573b7ada17ebe64096f7948"
    }
  },
  "error": ""
}

Permission denied:

{
  "time": "2017-05-23T15:28:43Z",
  "type": "request",
  "auth": {
    "client_token": "hmac-sha256:6e146104bd1d8df87b2c382e50c016fd30f14d821db8b9fd3c9fb079d72a3171",
    "accessor": "414f663d-32f2-9cfe-dab3-dccf6a2b3c6a",
    "display_name": "token-testuser",
    "policies": [
      "default"
    ],
    "metadata": {
      "test": "meta"
    }
  },
  "request": {
    "id": "cb58a747-2917-3cfc-a6ac-b4e33665abe4",
    "operation": "read",
    "client_token": "hmac-sha256:6e146104bd1d8df87b2c382e50c016fd30f14d821db8b9fd3c9fb079d72a3171",
    "client_token_accessor": "414f663d-32f2-9cfe-dab3-dccf6a2b3c6a",
    "path": "secret/test",
    "data": null,
    "remote_address": "127.0.0.1",
    "wrap_ttl": 0,
    "headers": {}
  },
  "error": "permission denied"
}
{
  "time": "2017-05-23T15:28:43Z",
  "type": "response",
  "auth": {
    "client_token": "hmac-sha256:6e146104bd1d8df87b2c382e50c016fd30f14d821db8b9fd3c9fb079d72a3171",
    "accessor": "414f663d-32f2-9cfe-dab3-dccf6a2b3c6a",
    "display_name": "token-testuser",
    "policies": [
      "default"
    ],
    "metadata": {
      "test": "meta"
    }
  },
  "request": {
    "id": "cb58a747-2917-3cfc-a6ac-b4e33665abe4",
    "operation": "read",
    "client_token": "hmac-sha256:6e146104bd1d8df87b2c382e50c016fd30f14d821db8b9fd3c9fb079d72a3171",
    "client_token_accessor": "414f663d-32f2-9cfe-dab3-dccf6a2b3c6a",
    "path": "secret/test",
    "data": null,
    "remote_address": "127.0.0.1",
    "wrap_ttl": 0,
    "headers": {}
  },
  "response": {
    "data": {
      "error": "hmac-sha256:db6e100d6efef4dfa2b45537ada71ddd9f4988175858988cd1a361a9a42251bb"
    }
  },
  "error": "1 error occurred:\n\n* permission denied"
}

bkrodgers · 2017-05-23T15:57:57Z

Oops, didn't run tests. Fix coming.

vishalnayak · 2017-05-23T16:39:55Z

audit/format.go

+			DisplayName:   auth.DisplayName,
+			Policies:      auth.Policies,
+			Metadata:      auth.Metadata,
+			RemainingUses: req.ClientTokenRemainingUses,


I think we had omitted the ClientTokenRemainingUses in the response intentionally. @jefferai What do you think?

Sure, let me know. I can pull it back out (and maybe add a comment noting the inconsistency is intentional). In the meantime, pushed a fix for the tests that failed, including adding some additional fields.

I think we had too. At the moment I don't remember the context around it; it may be in comments in the PR that introduced that change.

Sorry for the noise. I couldn't find such a conversation in the earlier PR (#2437). On a second thought, this is looking fine to me.

So leave it in as I have it, then?

bkrodgers · 2017-06-01T19:08:16Z

@jefferai Anything else you need from me on this? No major rush, just wanted to cross it off my to-do list. I noticed we'd diverged and had some conflicts, so I've rebased and updated the test code a little to reflect the move of the salt init.

bkrodgers · 2017-06-01T19:54:30Z

I'm seeing test failures on things that I don't think are related to my change:

2017/06/01 19:14:38.175127 [INFO ] core: mount tuning successful: path=foo/
2017/06/01 19:14:38.175789 [ERROR] sys: tuning failed: path=foo/ error=new backend default lease TTL of 259200000 greater than system max lease TTL of 2764800
2017/06/01 19:14:38.177050 [INFO ] core: mount tuning successful: path=foo/
2017/06/01 19:14:38.177659 [ERROR] sys: tuning failed: path=foo/ error=new backend default lease TTL of 259203600 greater than backend max lease TTL of 259200000
2017/06/01 19:14:38.178374 [ERROR] sys: tun```

Any thoughts why?

jefferai · 2017-06-02T14:50:13Z

@bkrodgers I'm not super thrilled with this PR, so I was holding off while thinking about it.

It goes way beyond "parity for failed requests" and adds a lot of extra fields. Some of them we specifically didn't add before and I've been trying to remember why. Some of them have the potential to be very, very verbose, and seriously balloon the size of audit log.

bkrodgers · 2017-06-02T18:12:28Z

So the main thing I want out of this PR is to see display name, policies, and metadata on actions denied by ACL. The other parts to fill out the existing token fields that weren't being populated under any circumstance (but were always part of the log entry) and the token count one were just efforts to sync things up. I'd be happy to pull them out if those are the parts you're concerned about.

jefferai · 2017-06-05T14:34:11Z

Metadata can be very, very large. It's one of my main concerns. In theory display name can, too.

What is the use-case here? I have a couple in mind, but want to know yours...

bkrodgers · 2017-06-05T19:50:57Z

Keep in mind that all this PR changes for metadata and display-name is to write those values in the scenario where a user tries access something but is denied by ACL. The metadata and display-name values are already being logged in every successful request. So I don't see the concern with additional size. 99% of the audit log entries will already have these values in them.

My use case for wanting it on ACL denied entries is that even if they are denied, if someone is frequently trying to access something their policies don't allow them to access, I may want to follow up with them. Once their token expires, I can't use the accessor to pull that info, and it's much easier to work with if it's right there in the audit log anyway. But again, this only adds that data in that one narrow case. I do have plenty of other cases where it already is logging this info that I wouldn't want to see go away. If you're concerned these are already taking up too much space in the audit log and are thinking about removing them, that would be very problematic. Having permanent and integrated access (as in not based on token lifetime, and not needing to look it up outside the logging tool) in the audit log to info about who performed operations is a core function of the audit log to me.

It is true, however, that I'm adding data to every log entry with the addition of the code to populate auth.client_token** and auth.display_name. The fields currently get logged on every request with an empty value -- the code to populate them simply wasn't there, but they were getting logged in the json as empty, which I thought was confusing. I can remove that if you're concerned about those adding too much to the size. I think it makes sense for them to be logged in the auth block along with the rest of the auth related info, but for the time being it is duplicating those two fields on request.

jefferai · 2017-06-05T20:11:34Z

The metadata and display-name values are already being logged in every successful request.

Huh. I didn't know that. That's unfortunate, although I guess for your use-case it's an enabling reason.

If you're concerned these are already taking up too much space in the audit log and are thinking about removing them, that would be very problematic.

Dude, give us a little credit. You've been around long enough :-)

jefferai · 2017-06-05T20:25:24Z

vault/request_handling.go

@@ -171,7 +171,7 @@ func (c *Core) handleRequest(req *logical.Request) (retResp *logical.Response, r
 		if errType != nil {
 			retErr = multierror.Append(retErr, errType)
 		}
-		return logical.ErrorResponse(ctErr.Error()), nil, retErr
+		return logical.ErrorResponse(ctErr.Error()), auth, retErr


I don't believe this change is necessary.

It is necessary to get it to log the info in the response entry as well. In the case of an error, including the ACL error scenario I'm trying to address here, the auth object from this return statement then gets passed to c.auditBroker.LogResponse on line 107.

jefferai · 2017-06-05T22:04:26Z

Ah, ok. I figured I was missing something there.

Basically: I really dislike this PR, but 99.9% of that comes from the fact that I really wish I could change a lot about the structure of the audit logs, so anything that adds more information on top of what's there (making it even more impossible to change later) just makes me super duper sad. But it is a sadness I will have to deal with because it is a sailed ship.

bkrodgers · 2017-06-05T22:08:07Z

Yeah, I hear ya. No question the audit log structure could be cleaner. Maybe someday you can add a "v2" format and default new audit backend mounts to it, leaving current backend mounts on "v1."

jefferai · 2017-06-05T22:19:28Z

Vault's HTTP API is in even more need of that, but it's not an easy thing to foist on people.

bkrodgers · 2017-06-05T22:31:14Z

Oh I know, I've been on both sides of that. You know I'm always happy to help provide any feedback on such changes though!

jefferai added this to the 0.7.3 milestone May 23, 2017

vishalnayak reviewed May 23, 2017

View reviewed changes

vishalnayak approved these changes May 23, 2017

View reviewed changes

vishalnayak reviewed May 23, 2017

View reviewed changes

bkrodgers added 4 commits June 1, 2017 13:01

Log auth info on permission denied due to ACL

1e4a1c8

Populate ClientToken and Accessor in the 'auth' audit object.

b5f6078

Audit formatter test fixes/expansions

56d6aff

Updated audit tests since the salt initialization has been moved

ac83133

bkrodgers force-pushed the audit-request-auth branch from 7fda0b0 to ac83133 Compare June 1, 2017 19:06

jefferai reviewed Jun 5, 2017

View reviewed changes

jefferai merged commit d4fb262 into hashicorp:master Jun 5, 2017

bkrodgers deleted the audit-request-auth branch June 5, 2017 22:49

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Log auth info on permission denied due to ACL #2754

Log auth info on permission denied due to ACL #2754

bkrodgers commented May 23, 2017

vishalnayak May 23, 2017

bkrodgers May 23, 2017

vishalnayak left a comment

bkrodgers commented May 23, 2017

bkrodgers commented May 23, 2017

bkrodgers commented May 23, 2017

vishalnayak May 23, 2017

bkrodgers May 23, 2017

jefferai May 23, 2017

vishalnayak May 23, 2017

bkrodgers May 23, 2017

vishalnayak May 23, 2017

bkrodgers commented Jun 1, 2017

bkrodgers commented Jun 1, 2017

jefferai commented Jun 2, 2017

bkrodgers commented Jun 2, 2017

jefferai commented Jun 5, 2017

bkrodgers commented Jun 5, 2017

jefferai commented Jun 5, 2017

jefferai Jun 5, 2017

bkrodgers Jun 5, 2017

jefferai commented Jun 5, 2017

bkrodgers commented Jun 5, 2017

jefferai commented Jun 5, 2017

bkrodgers commented Jun 5, 2017

Log auth info on permission denied due to ACL #2754

Log auth info on permission denied due to ACL #2754

Conversation

bkrodgers commented May 23, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

vishalnayak left a comment

Choose a reason for hiding this comment

bkrodgers commented May 23, 2017

bkrodgers commented May 23, 2017

bkrodgers commented May 23, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bkrodgers commented Jun 1, 2017

bkrodgers commented Jun 1, 2017

jefferai commented Jun 2, 2017

bkrodgers commented Jun 2, 2017

jefferai commented Jun 5, 2017

bkrodgers commented Jun 5, 2017

jefferai commented Jun 5, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jefferai commented Jun 5, 2017

bkrodgers commented Jun 5, 2017

jefferai commented Jun 5, 2017

bkrodgers commented Jun 5, 2017