Basic audit log #27087

soltysh · 2016-06-08T22:02:03Z

Fixes #2203 by introducing simple audit logging, including the information about impersonation. We currently have something identical in openshift, but I'm open to any suggestions. Sample logs look like that:

as <self>:

AUDIT: id="75114bb5-970a-47d5-a5f1-1e99cea0574c" ip="127.0.0.1" method="GET" user="test-admin" as="<self>" namespace="openshift" uri="/api/v1/namespaces/openshift/pods/python"
AUDIT: id="75114bb5-970a-47d5-a5f1-1e99cea0574c" response=200

as user:

AUDIT: id="b0a443ae-f7d8-408c-a355-eb9501fd5c59" ip="192.168.121.118" method="GET" user="system:admin" as="test-admin" namespace="openshift" uri="/api/v1/namespaces/openshift/pods/python"
AUDIT: id="b0a443ae-f7d8-408c-a355-eb9501fd5c59" response=200

* Add basic audit logging

@ericchiang @smarterclayton @roberthbailey @erictune @ghodss

This change is

ericchiang · 2016-06-08T22:41:49Z

pkg/genericapiserver/genericapiserver.go

@@ -475,6 +479,10 @@ func (s *GenericAPIServer) init(c *Config) {

 	attributeGetter := apiserver.NewRequestAttributeGetter(s.RequestContextMapper, s.NewRequestInfoResolver())
 	handler = apiserver.WithAuthorizationCheck(handler, attributeGetter, s.authorizer)
+	if c.EnableAudit {
+		// audit handler must comes before the impersonationFilter to read the original user
+		handler = audit.WithAudit(handler, s.RequestContextMapper)


Should this come before authorization? I imagine we'd want to capture authentication requests that were denied for some reason or another.

Woops, sorry it already does. (Got my middleware logic backwards)

ericchiang · 2016-06-08T22:45:16Z

This is great. Few comments:

Would like to see a pluggable interface for this. We'd like implementations other than stderr logging pretty quickly.
I don't see how we could extend this to provide information such as specifics around authenticator, authorizer, or admission controller. For example, which authentication strategy was used, or which admission controller denied a particular request. This was brought up in the initial feature specs[0], but I don't know if that's too much trouble to try to accomplish.

[0] #2203 (comment)

lavalamp · 2016-06-08T22:56:26Z

pkg/apiserver/audit/audit.go

+}
+
+func (a *auditResponseWriter) WriteHeader(code int) {
+	glog.Infof("AUDIT: id=%q response=\"%d\"", a.id, code)


Is writing to stdout really the best way to produce audit logs? I guess I'd expect a separate output file, though I've never made audit logs before.

A separate log file is not uncommon (depends on whether you want your logs
in one place or two places) - putting this behind an interface certainly
can't hurt though, and fleshing out the implementation.

On Wed, Jun 8, 2016 at 6:56 PM, Daniel Smith notifications@github.com
wrote:

In pkg/apiserver/audit/audit.go
#27087 (comment)
:

"github.com/golang/glog"

"github.com/pborman/uuid"

"k8s.io/kubernetes/pkg/api"

utilnet "k8s.io/kubernetes/pkg/util/net"
+)

+// auditResponseWriter implements http.ResponseWriter interface.
+type auditResponseWriter struct {

http.ResponseWriter

id string
+}

+func (a *auditResponseWriter) WriteHeader(code int) {

glog.Infof("AUDIT: id=%q response="%d"", a.id, code)

Is writing to stdout really the best way to produce audit logs? I guess
I'd expect a separate output file, though I've never made audit logs before.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/kubernetes/kubernetes/pull/27087/files/752c551c39be25f16e03d37bec8a3c2567467370#r66355213,
or mute the thread
https://github.com/notifications/unsubscribe/ABG_p4gePInwAQlDTfd0K-tGyId2SyZeks5qJ0iqgaJpZM4Ixcs-
.

The log is already hard enough to read-- I think I'd prefer a separate file.

Also I think it might be good to put the audit ID in the context? I guess
we can do that when we have a use case.

On Wed, Jun 8, 2016 at 4:07 PM, Clayton Coleman notifications@github.com
wrote:

In pkg/apiserver/audit/audit.go
#27087 (comment)
:

"github.com/golang/glog"

"github.com/pborman/uuid"

"k8s.io/kubernetes/pkg/api"

utilnet "k8s.io/kubernetes/pkg/util/net"
+)

+// auditResponseWriter implements http.ResponseWriter interface.
+type auditResponseWriter struct {

http.ResponseWriter

id string
+}

+func (a *auditResponseWriter) WriteHeader(code int) {

glog.Infof("AUDIT: id=%q response="%d"", a.id, code)

A separate log file is not uncommon (depends on whether you want your logs
in one place or two places) - putting this behind an interface certainly
can't hurt though, and fleshing out the implementation.
… <#m_-3854526224780300919_>
On Wed, Jun 8, 2016 at 6:56 PM, Daniel Smith _@_.***> wrote: In
pkg/apiserver/audit/audit.go <#27087 (comment)
https://github.com/kubernetes/kubernetes/pull/27087#discussion_r66355213>
: > + > + "github.com/golang/glog" > + "github.com/pborman/uuid" > + > + "
k8s.io/kubernetes/pkg/api" > + utilnet "k8s.io/kubernetes/pkg/util/net" >
+) > + > +// auditResponseWriter implements http.ResponseWriter interface.

+type auditResponseWriter struct { > + http.ResponseWriter > + id string
+} > + > +func (a *auditResponseWriter) WriteHeader(code int) { > +
glog.Infof("AUDIT: id=%q response="%d"", a.id, code) Is writing to
stdout really the best way to produce audit logs? I guess I'd expect a
separate output file, though I've never made audit logs before. — You are
receiving this because you were mentioned. Reply to this email directly,
view it on GitHub <
https://github.com/kubernetes/kubernetes/pull/27087/files/752c551c39be25f16e03d37bec8a3c2567467370#r66355213>,
or mute the thread <
https://github.com/notifications/unsubscribe/ABG_p4gePInwAQlDTfd0K-tGyId2SyZeks5qJ0iqgaJpZM4Ixcs->
.

—
You are receiving this because you were assigned.
Reply to this email directly, view it on GitHub
https://github.com/kubernetes/kubernetes/pull/27087/files/752c551c39be25f16e03d37bec8a3c2567467370#r66356421,
or mute the thread
https://github.com/notifications/unsubscribe/AAngljnZIzH5MvZkcNtqBs9oe67OxgN5ks5qJ0sjgaJpZM4Ixcs-
.

The log is already hard enough to read-- I think I'd prefer a separate file.

I don't mind that, can you please tell me how to do it with glog though? I haven't see any possibility there :( But I agree with Clayton about placing it behind an interface.

Also I think it might be good to put the audit ID in the context? I guess we can do that when we have a use case.

Makes sense as well.

Just don't use glog may be the easiest :)

On Thu, Jun 9, 2016 at 7:36 AM, Maciej Szulik notifications@github.com
wrote:

In pkg/apiserver/audit/audit.go
#27087 (comment)
:

"github.com/golang/glog"

"github.com/pborman/uuid"

"k8s.io/kubernetes/pkg/api"

utilnet "k8s.io/kubernetes/pkg/util/net"
+)

+// auditResponseWriter implements http.ResponseWriter interface.
+type auditResponseWriter struct {

http.ResponseWriter

id string
+}

+func (a *auditResponseWriter) WriteHeader(code int) {

glog.Infof("AUDIT: id=%q response="%d"", a.id, code)

The log is already hard enough to read-- I think I'd prefer a separate
file.

I don't mind that, can you please tell me how to do it with glog though? I
haven't see any possibility there :( But I agree with Clayton about placing
it behind an interface.

Also I think it might be good to put the audit ID in the context? I guess
we can do that when we have a use case.

Makes sense as well.

—
You are receiving this because you were assigned.
Reply to this email directly, view it on GitHub
https://github.com/kubernetes/kubernetes/pull/27087/files/752c551c39be25f16e03d37bec8a3c2567467370#r66452677,
or mute the thread
https://github.com/notifications/unsubscribe/AAnglhR5eD-2XOT8-YcGg8_0JQ1dW5Myks5qKCTVgaJpZM4Ixcs-
.

I'll go with Clayton's solution of passing a writer, how that will be resolved further we can leave for other time :)

Separate file seems like a good default.

I'm going to want to add an interface that can call out to a webhook to post a batch of these. But that can wait for a later PR. Going with passing Writer in this PR seems fine.

lavalamp · 2016-06-08T23:01:23Z

So I think the most important thing about audit logging is probably certainty that it always gets called for all api accesses. I think you need a testing strategy for this.

I also think this probably gives incorrect or unhelpful output for watches, port forwarding / attach / exec, proxy requests.

erictune · 2016-06-09T23:56:40Z

I like this. Thanks for writing it.

roberthbailey · 2016-06-23T23:33:32Z

/cc @cjcullen

erictune · 2016-06-29T23:41:32Z

@maisem you have some expertise in this area: would you take a look at the list of things that are being audit logged?

erictune · 2016-06-29T23:42:00Z

pkg/apiserver/audit/audit.go

+//    - impersonated user for the operation
+//    - namespace of the request or <none>
+//    - uri is the full URI as requested
+// 2. the response line containing the unique id from 1 and response code


@maisem take a look at above comment

Can you split this line into the same format as 1.
As it is right now, I thought it meant that we log the response body.

I guess my question is should we log the response/request body as well?

Can you split this line into the same format as 1.
As it is right now, I thought it meant that we log the response body.

Not sure what you need here. Basically it's split into two lines because of the response code. I want to have two separate logs for the matter of knowing which and when went in. I don't see any value in repeating all data in the 2nd line.

I guess my question is should we log the response/request body as well?

If you want to have full request/response body just increase the loglevel. This is meant rather as just a general audit information, hopefully at some point in time landing in a separate file.

Sorry, I meant the comment line.

2. the response line containing: - the unique id from 1 - response code

😊 sure thing

Logging the whole body for a secret create request seems like a bad idea.

On Thu, Jun 30, 2016 at 7:34 AM, Maciej Szulik notifications@github.com
wrote:

In pkg/apiserver/audit/audit.go
#27087 (comment)
:

+var _ http.CloseNotifier = &fancyResponseWriterDelegator{}
+var _ http.Flusher = &fancyResponseWriterDelegator{}
+var _ http.Hijacker = &fancyResponseWriterDelegator{}
+
+// WithAudit is responsible for logging audit information for all the
+// request coming to server. Each audit log contains two entries:
+// 1. the request line containing:
+// - unique id allowing to match the response line (see 2)
+// - source ip of the request
+// - HTTP method being invoked
+// - original user invoking the operation
+// - impersonated user for the operation
+// - namespace of the request or
+// - uri is the full URI as requested
+// 2. the response line containing the unique id from 1 and response code

😊 sure thing

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/kubernetes/kubernetes/pull/27087/files/752c551c39be25f16e03d37bec8a3c2567467370#r69143282,
or mute the thread
https://github.com/notifications/unsubscribe/AHuudsn2QQ9HN0VVhLSrMxG9Krok0TzZks5qQ9P5gaJpZM4Ixcs-
.

I agree, but that's solvable by redacting some of the fields.
It would be good to know what the caller was generating secrets for.

It would be nice if the id generated here was available for log correlation at the api level.

Yet again, that falls into the category of debugging server, which can be easily achieved with loglevel=8. Audit is different, imho.

soltysh · 2016-06-30T14:27:45Z

I'll try to update this PR tomorrow, now that 1.4 queue is open.

soltysh · 2016-07-01T12:15:22Z

Updated, ptal.

amouat · 2016-07-06T14:06:12Z

pkg/apiserver/audit/audit.go

+}
+
+func (a *auditResponseWriter) WriteHeader(code int) {
+	fmt.Fprintf(a.out, "AUDIT: id=%q response=\"%d\"", a.id, code)


Would it make sense to add a newline here? At the moment all the logs appear in a single line which is a bit of a pain.

True, I totally forgot about that one when switching from glog to Fprintf.

+1 for newline

alexbrand · 2016-07-08T13:48:21Z

Should the audit log messages include a timestamp?

lavalamp · 2016-07-12T17:27:27Z

pkg/apiserver/audit/audit.go

+		}
+		id := uuid.NewRandom().String()
+
+		fmt.Fprintf(out, "AUDIT: id=%q ip=%q method=%q user=%q as=%q namespace=%q uri=%q",


What do you think about making this more structured, e.g. json or yaml?

What do you mean by that? Printing yaml/json here, eg:

audit: id: 123.456 ip: 192.168.1.1 method: POST ...

Wouldn't that make the log too long? With above you have just one line for each call, easily greppable.

I think key-value as it's written is a good first option since it's most amenable to systems like splunk and other conventional security logging utilities. If any other formats are added (e.g. JSON blobs on one one line each) they should be a configuration option.

Ah, ok. If this is a common format then that's totally fine with me.

On Tue, Jul 12, 2016 at 5:01 PM, Sam Ghods notifications@github.com wrote:

In pkg/apiserver/audit/audit.go
#27087 (comment)
:

+// - response code
+func WithAudit(handler http.Handler, requestContextMapper api.RequestContextMapper, out io.Writer) http.Handler {

return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {

ctx, _ := requestContextMapper.Get(req)

user, _ := api.UserFrom(ctx)

asuser := req.Header.Get("Impersonate-User")

if len(asuser) == 0 {

asuser = "<self>"

}

namespace := api.NamespaceValue(ctx)

if len(namespace) == 0 {

namespace = "<none>"

}

id := uuid.NewRandom().String()

fmt.Fprintf(out, "AUDIT: id=%q ip=%q method=%q user=%q as=%q namespace=%q uri=%q",

I think key-value as it's written is a good first option since it's most
amenable to systems like splunk and other conventional security logging
utilities. If any other formats are added (e.g. JSON blobs on one one line)
they should be a configuration option.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/kubernetes/kubernetes/pull/27087/files/39a81bd9c13e88bfa0da8c2bc6f91cf4ae450a28#r70544596,
or mute the thread
https://github.com/notifications/unsubscribe/AAnglp0vFSO0I3GTyjzzU862gyP4AwbJks5qVCrpgaJpZM4Ixcs-
.

lavalamp · 2016-07-12T17:29:14Z

+1 for timestapm. Looks close. It would be super awesome if you made the ordinary log messages include the audit log ID-- that would make it easier to trace a crash back to a request.

I really want this because right now we've got no way to see request sources for requests that are still ongoing.

soltysh · 2016-07-12T20:10:45Z

@lavalamp yeah, I'll try to address the suggestions tomorrow.

It would be super awesome if you made the ordinary log messages include the audit log ID-- that would make it easier to trace a crash back to a request.

Can you elaborate a bit more what do you want here? Not sure I follow.

amouat · 2016-07-12T20:22:33Z

@soltysh @lavalamp I think I understand, but I would suggest it is out of scope for this. The ID here is necessary to correlate the request and the response. @lavalamp is suggesting that all k8s logs that can be traced back to a request include this ID. If this was done, an error in any part of k8s could be traced back to the API call that triggered it. I'm not sure this is feasible, but it's certainly a nice idea.

soltysh · 2016-08-11T14:05:50Z

@sttts added the 3 options (maxbackup, maxage and maxsize) to configure the logging as discussed on IRC and fixed the break, as well. ptal

sttts · 2016-08-11T14:09:44Z

lgtm

Review status: 1 of 4 files reviewed at latest revision, 2 unresolved discussions.

Comments from Reviewable

soltysh · 2016-08-12T08:37:19Z

Fixed boilerplate in the newly added files, which was causing jenkins failure. Applying label based on previous approval.

soltysh · 2016-08-12T08:42:01Z

Review status: 0 of 4 files reviewed at latest revision, 2 unresolved discussions.

pkg/apiserver/audit/audit_test.go, line 47 [r2] (raw file):

Previously, deads2k (David Eads) wrote…

Go breaks at the end of the block by default. You have to specify fallthrough to drop through.

Fixed

pkg/genericapiserver/options/server_run_options.go, line 299 [r2] (raw file):

Previously, sttts (Dr. Stefan Schimanski) wrote…

Default for MaxAge and MaxBackup is unlimited: https://github.com/natefinch/lumberjack#type-logger. We should set sane values, e.g. 7 days.

Added `--audit-log-maxage`, `--audit-log-maxbackup` and `--audit-log-maxsize` to address that.

Comments from Reviewable

soltysh · 2016-08-12T08:44:50Z

pkg/genericapiserver/options/server_run_options.go, line 299 [r2] (raw file):

Previously, soltysh (Maciej Szulik) wrote…

Added --audit-log-maxage, --audit-log-maxbackup and --audit-log-maxsize to address that.

OK

Comments from Reviewable

soltysh · 2016-08-12T08:55:36Z

Reviewed 4 of 4 files at r3.
Review status: all files reviewed at latest revision, 1 unresolved discussion.

Comments from Reviewable

soltysh · 2016-08-12T10:27:38Z

Rebased and fixed the golint error.

k8s-bot · 2016-08-12T11:03:00Z

GCE e2e build/test passed for commit 24f1e1e.

sttts · 2016-08-12T11:42:42Z

Reviewed 4 of 4 files at r3, 2 of 2 files at r4.
Review status: all files reviewed at latest revision, all discussions resolved.

Comments from Reviewable

k8s-github-robot · 2016-08-12T11:51:48Z

@k8s-bot test this [submit-queue is verifying that this PR is safe to merge]

k8s-bot · 2016-08-12T12:31:28Z

GCE e2e build/test passed for commit 24f1e1e.

k8s-github-robot · 2016-08-12T12:31:31Z

Automatic merge from submit-queue

googlebot added the cla: yes label Jun 8, 2016

soltysh added area/security team/cluster labels Jun 8, 2016

k8s-github-robot assigned lavalamp Jun 8, 2016

k8s-github-robot added size/L Denotes a PR that changes 100-499 lines, ignoring generated files. release-note-label-needed labels Jun 8, 2016

ericchiang reviewed Jun 8, 2016
View reviewed changes

lavalamp reviewed Jun 8, 2016
View reviewed changes

ericchiang mentioned this pull request Jun 10, 2016

Audit logs #2203

Closed

alex-mohr assigned cjcullen Jun 23, 2016

alex-mohr added the sig/auth Categorizes an issue or PR as relevant to SIG Auth. label Jun 23, 2016

erictune reviewed Jun 29, 2016
View reviewed changes

erictune mentioned this pull request Jun 30, 2016

Track which user created resources #13925

Closed

soltysh force-pushed the audit_log branch from 752c551 to 39a81bd Compare July 1, 2016 12:14

amouat reviewed Jul 6, 2016
View reviewed changes

lavalamp reviewed Jul 12, 2016
View reviewed changes

soltysh force-pushed the audit_log branch from 2867772 to ff27f0d Compare August 11, 2016 14:04

soltysh added this to the v1.4 milestone Aug 11, 2016

soltysh force-pushed the audit_log branch from ff27f0d to 4a2a48a Compare August 12, 2016 08:36

soltysh added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Aug 12, 2016

k8s-github-robot removed the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Aug 12, 2016

soltysh added release-note Denotes a PR that will be considered when it comes time to generate release notes. lgtm "Looks good to me", indicates that a PR is ready to be merged. and removed release-note-label-needed labels Aug 12, 2016

soltysh force-pushed the audit_log branch from 4a2a48a to ac12d80 Compare August 12, 2016 09:30

k8s-github-robot removed the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Aug 12, 2016

sttts added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Aug 12, 2016

Basic audit log

24f1e1e

soltysh force-pushed the audit_log branch from ac12d80 to 24f1e1e Compare August 12, 2016 10:27

k8s-github-robot removed the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Aug 12, 2016

soltysh added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Aug 12, 2016

k8s-github-robot merged commit 510924b into kubernetes:master Aug 12, 2016

soltysh deleted the audit_log branch August 12, 2016 20:34

nikhiljindal mentioned this pull request May 8, 2017

Proposal: Record which user created an object #13306

Closed

Basic audit log #27087

Basic audit log #27087

Conversation

soltysh commented Jun 8, 2016 • edited by k8s-oncall Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ericchiang commented Jun 8, 2016

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

Choose a reason for hiding this comment

lavalamp commented Jun 8, 2016

erictune commented Jun 9, 2016

roberthbailey commented Jun 23, 2016

erictune commented Jun 29, 2016

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

Choose a reason for hiding this comment

maisem Jun 30, 2016 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

soltysh commented Jun 30, 2016

soltysh commented Jul 1, 2016

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

alexbrand commented Jul 8, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ghodss Jul 13, 2016 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

lavalamp commented Jul 12, 2016

soltysh commented Jul 12, 2016

amouat commented Jul 12, 2016

soltysh commented Aug 11, 2016

sttts commented Aug 11, 2016

soltysh commented Aug 12, 2016

soltysh commented Aug 12, 2016

soltysh commented Aug 12, 2016

soltysh commented Aug 12, 2016

soltysh commented Aug 12, 2016

k8s-bot commented Aug 12, 2016

sttts commented Aug 12, 2016

k8s-github-robot commented Aug 12, 2016

k8s-bot commented Aug 12, 2016

k8s-github-robot commented Aug 12, 2016

soltysh commented Jun 8, 2016 •

edited by k8s-oncall

Loading

maisem Jun 30, 2016 •

edited

Loading

ghodss Jul 13, 2016 •

edited

Loading