implements structured logging for apiserver #113

BugRoger · 2017-12-07T17:44:58Z

api | ts=2017-12-07T17:37:00.746191096Z caller=github.com/sapcc/kubernikus/pkg/api/rest/configure.go:31 msg="Serving kubernikus at http://127.0.0.1:5100"
api | ts=2017-12-07T17:37:03.981714807Z caller=github.com/sapcc/kubernikus/pkg/util/log/gophercloud.go:52 project=5d725ddf97664a16b011e8a8dd75772b auth=token method=POST host=identity-3.eu-nl-1.cloud.sap path=/v3/auth/tokens status=201 size=12081 id=req-df05b676-9c98-4043-91d1-e3d251ffc1f2 took=174.10291ms v=2
api | ts=2017-12-07T17:37:03.994440467Z caller=github.com/sapcc/kubernikus/pkg/client/openstack/scoped/logging.go:35 project=5d725ddf97664a16b011e8a8dd75772b auth=token msg=authenticated took=187.137236ms v=2
api | ts=2017-12-07T17:37:04.229706102Z caller=github.com/sapcc/kubernikus/pkg/util/log/gophercloud.go:52 project=5d725ddf97664a16b011e8a8dd75772b auth=token method=GET host=network-3.eu-nl-1.cloud.sap path=/v2.0/routers status=200 size=-1 id=req-e23dfbde-12a7-4df1-98ac-7920bc3a2e8b took=235.173194ms v=2
api | ts=2017-12-07T17:37:04.432480469Z caller=github.com/sapcc/kubernikus/pkg/util/log/gophercloud.go:52 project=5d725ddf97664a16b011e8a8dd75772b auth=token method=GET host=network-3.eu-nl-1.cloud.sap path=/v2.0/ports device_id=21adab1b-b8ae-4d44-8a1f-fcb0f3258d01 device_owner=network:router_interface status=200 size=-1 id=req-b4d47b35-cce8-4b83-b8af-73b7e41f10de took=202.045165ms v=2
api | ts=2017-12-07T17:37:04.621683785Z caller=github.com/sapcc/kubernikus/pkg/util/log/gophercloud.go:52 project=5d725ddf97664a16b011e8a8dd75772b auth=token method=GET host=network-3.eu-nl-1.cloud.sap path=/v2.0/networks/48317f3c-13ae-4300-9101-353125b9aa9e status=200 size=-1 id=req-7f529b64-0ed5-4707-af7d-80ebc656fbd7 took=188.319113ms v=2
api | ts=2017-12-07T17:37:04.809404826Z caller=github.com/sapcc/kubernikus/pkg/util/log/gophercloud.go:52 project=5d725ddf97664a16b011e8a8dd75772b auth=token method=GET host=network-3.eu-nl-1.cloud.sap path=/v2.0/networks/48317f3c-13ae-4300-9101-353125b9aa9e status=200 size=-1 id=req-5cd86e08-2e50-443a-95ac-449a95d829b6 took=187.269636ms v=2
api | ts=2017-12-07T17:37:05.007636259Z caller=github.com/sapcc/kubernikus/pkg/util/log/gophercloud.go:52 project=5d725ddf97664a16b011e8a8dd75772b auth=token method=GET host=network-3.eu-nl-1.cloud.sap path=/v2.0/subnets/dbef5f63-0df6-4438-8979-dd0c1fbb99ab status=200 size=-1 id=req-746e5d27-87f1-436e-ab9e-3c5c82bee1ee took=197.773135ms v=2
api | ts=2017-12-07T17:37:05.165771023Z caller=github.com/sapcc/kubernikus/pkg/util/log/gophercloud.go:52 project=5d725ddf97664a16b011e8a8dd75772b auth=token method=GET host=compute-3.eu-nl-1.cloud.sap path=/v2/5d725ddf97664a16b011e8a8dd75772b/os-keypairs status=200 size=-1 id=req-a0d66208-84ba-45c0-8753-072d9bb30e04 took=157.759571ms v=2
api | ts=2017-12-07T17:37:05.401391954Z caller=github.com/sapcc/kubernikus/pkg/util/log/gophercloud.go:52 project=5d725ddf97664a16b011e8a8dd75772b auth=token method=GET host=compute-3.eu-nl-1.cloud.sap path=/v2/5d725ddf97664a16b011e8a8dd75772b/os-security-groups status=200 size=-1 id=req-83144cb9-b7e4-4399-aacb-cfb17be5ab5f took=235.225408ms v=2
api | ts=2017-12-07T17:37:05.571716528Z caller=github.com/sapcc/kubernikus/pkg/util/log/gophercloud.go:52 project=5d725ddf97664a16b011e8a8dd75772b auth=token method=GET host=compute-3.eu-nl-1.cloud.sap path=/v2/5d725ddf97664a16b011e8a8dd75772b/flavors/detail status=200 size=-1 id=req-8745a964-a133-48b9-90dc-433b886ddda1 took=169.489954ms v=2
api | ts=2017-12-07T17:37:05.57490622Z caller=github.com/sapcc/kubernikus/pkg/client/openstack/scoped/logging.go:19 project=5d725ddf97664a16b011e8a8dd75772b auth=token msg="fetched metadata" flavors=20 keypairs=1 routers=1 security_groups=1 took=1.580461341s
api | ts=2017-12-07T17:37:05.57524819Z caller=github.com/sapcc/kubernikus/pkg/util/log/middleware.go:36 method=GET host=127.0.0.1 path=/api/v1/openstack/metadata status=200 size=1035 took=2.029857786s v=1

BugRoger · 2017-12-07T17:48:48Z

pkg/util/log/gophercloud.go

+		if response != nil {
+			logger = kitlog.With(logger,
+				"status", response.StatusCode,
+				"size", response.ContentLength,


why is this always -1? i suppose it needs to be wrapped into a buffer or something.

From the go docs:

ContentLength records the length of the associated content. The
value -1 indicates that the length is unknown. Unless Request.Method
is "HEAD", values >= 0 indicate that the given number of bytes may
be read from Body.

I think the server (openstack service) doesn't set the content-length header as this would require buffering the whole response before sending anything.

BugRoger · 2017-12-07T17:49:38Z

@databus23 please review. if ok, would rewrite the rest of the api-server and openstack clients

databus23 · 2017-12-07T21:22:46Z

pkg/client/openstack/scoped/logging.go

+		c.Logger.Log(
+			"msg", "authenticated",
+			"took", time.Since(begin),
+			"v", 2,


I'm wondering if we should log authentication errors at a higher level then successful auth attempts. Not sure what else is logged but when openstack auth is failing we should be able to see this without the need to enable verbose logging.

done for this specific instance

databus23 · 2017-12-07T21:45:34Z

pkg/util/log/gophercloud.go

+}
+
+func (lrt *loggingRoundTripper) RoundTrip(request *http.Request) (response *http.Response, err error) {
+	logger := kitlog.With(lrt.Logger,


Looking at the implementation of With it doesn't come for free. There is quite some shuffling around and allocations going on.
I think its pretty inefficient to prepare a single log line like this, especially using With in a loop. We should try to use the contextual loggers only if they are used for a longer period and for multiple log lines.

Optimized in 1393ff5

databus23 · 2017-12-07T21:48:11Z

pkg/util/log/middleware.go

+			host = request.RemoteAddr
+		}
+
+		privateLogger := kitlog.With(logger,


The statement above about using contextual loggers sparingly applies here.

databus23 · 2017-12-07T21:51:02Z

pkg/util/log/middleware.go

+		privateLogger := kitlog.With(logger,
+			"method", request.Method,
+			"host", host,
+			"path", request.URL.EscapedPath(),


missing the User-Agent here

databus23 · 2017-12-07T21:55:54Z

pkg/api/rest/configure_kubernikus.go

@@ -25,8 +18,7 @@ func configureFlags(api *operations.KubernikusAPI) {
 }

 func configureAPI(api *operations.KubernikusAPI) http.Handler {
-
-	return setupGlobalMiddleware(api.Serve(setupMiddlewares))
+	return api.Serve(setupMiddlewares)


Can we change this to return api.Serve and remove the setupMiddleware function?
I find these two levels of middleware confusing and never quite understood the intended use case for the inner middleware chain.

databus23

Looks good overall. Some minor remarks

databus23

I few last nits. Otherwise LGTM

databus23 · 2017-12-11T10:50:33Z

cmd/apiserver/main.go

-	"github.com/golang/glog"
+	kitLog "github.com/go-kit/kit/log"
+	"github.com/go-stack/stack"
+


ocd alarm.

I'm trying to only have 3 groups in the imports in the following order:

stdlib
[empty line]
external deps
[empty line]
kubernikus internal deps

databus23 · 2017-12-11T10:53:01Z

pkg/api/rest/configure_kubernikus.go

@@ -25,8 +18,9 @@ func configureFlags(api *operations.KubernikusAPI) {
 }

 func configureAPI(api *operations.KubernikusAPI) http.Handler {
-
-	return setupGlobalMiddleware(api.Serve(setupMiddlewares))
+	return api.Serve(func(handler http.Handler) http.Handler {


I think we can reduce this to return api.Serve, no?

Scratch that we can't

databus23 · 2017-12-11T10:57:48Z

pkg/util/log/gophercloud.go

+
+	transport := providerClient.HTTPClient.Transport
+	if transport == nil {
+		transport = &http.Transport{}


Shouldn't we do http.DefaultTransport here?

BugRoger requested a review from databus23 as a code owner December 7, 2017 17:44

BugRoger commented Dec 7, 2017

View reviewed changes

BugRoger changed the title ~~implements structured logging~~ implements structured logging for apiserver Dec 7, 2017

databus23 reviewed Dec 7, 2017

View reviewed changes

BugRoger force-pushed the logging_client branch 3 times, most recently from 29337d1 to b5aa4e5 Compare December 11, 2017 10:49

databus23 approved these changes Dec 11, 2017

View reviewed changes

BugRoger force-pushed the logging_client branch from b5aa4e5 to 04bb84f Compare December 11, 2017 12:40

implements structured logging

97943e6

BugRoger force-pushed the logging_client branch from 04bb84f to 97943e6 Compare December 11, 2017 12:47

Merge branch 'master' into logging_client

6941be5

BugRoger merged commit 34c02de into master Dec 11, 2017

BugRoger deleted the logging_client branch December 11, 2017 14:29

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

implements structured logging for apiserver #113

implements structured logging for apiserver #113

BugRoger commented Dec 7, 2017

BugRoger Dec 7, 2017

databus23 Dec 7, 2017

BugRoger commented Dec 7, 2017

databus23 Dec 7, 2017 •

edited

Loading

BugRoger Dec 11, 2017

databus23 Dec 7, 2017 •

edited

Loading

BugRoger Dec 8, 2017

databus23 Dec 7, 2017

BugRoger Dec 8, 2017

databus23 Dec 7, 2017

BugRoger Dec 8, 2017

databus23 Dec 7, 2017

databus23 left a comment

databus23 left a comment

databus23 Dec 11, 2017

databus23 Dec 11, 2017

databus23 Dec 11, 2017

databus23 Dec 11, 2017

BugRoger Dec 11, 2017

implements structured logging for apiserver #113

implements structured logging for apiserver #113

Conversation

BugRoger commented Dec 7, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

BugRoger commented Dec 7, 2017

databus23 Dec 7, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

databus23 Dec 7, 2017 • edited Loading

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

databus23 left a comment

Choose a reason for hiding this comment

databus23 left a 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

databus23 Dec 7, 2017 •

edited

Loading

databus23 Dec 7, 2017 •

edited

Loading