add logging middleware for server #785

devang-gaur · 2021-05-18T11:27:32Z

fixes #784

devang-gaur · 2021-05-18T13:08:05Z

Here's how the logs look :

./bin/terrascan server
2021-05-18T18:33:14.591+0530	info	http-server/start.go:61	registering routes...
2021-05-18T18:33:14.591+0530	info	http-server/start.go:65	Route GET - /health
2021-05-18T18:33:14.591+0530	info	http-server/start.go:65	Route POST - /v1/{iac}/{iacVersion}/{cloud}/local/file/scan
2021-05-18T18:33:14.591+0530	info	http-server/start.go:65	Route POST - /v1/{iac}/{iacVersion}/{cloud}/remote/dir/scan
2021-05-18T18:33:14.591+0530	info	http-server/start.go:65	Route GET - /k8s/webhooks/{apiKey}/logs
2021-05-18T18:33:14.591+0530	info	http-server/start.go:65	Route GET - /k8s/webhooks/logs/{uid}
2021-05-18T18:33:14.592+0530	info	http-server/start.go:65	Route POST - /v1/k8s/webhooks/{apiKey}/scan/validate
2021-05-18T18:33:14.592+0530	info	http-server/start.go:95	http server listening at port 9010
2021-05-18T18:33:19.345+0530	info	logging/logwriter.go:25	::1 - - "GET /health HTTP/1.1" 200 0
2021-05-18T18:33:42.464+0530	info	logging/logwriter.go:25	::1 - - "GET /health HTTP/1.1" 200 0
2021-05-18T18:33:53.427+0530	info	logging/logwriter.go:25	::1 - - "GET /health HTTP/1.1" 200 0
2021-05-18T18:34:01.815+0530	info	logging/logwriter.go:25	::1 - - "GET / HTTP/1.1" 404 0

In JSON fomat :

./bin/terrascan server --log-type json
{"level":"info","time":"2021-05-18T18:34:47.494+0530","file":"http-server/start.go:61","msg":"registering routes..."}
{"level":"info","time":"2021-05-18T18:34:47.494+0530","file":"http-server/start.go:65","msg":"Route GET - /health"}
{"level":"info","time":"2021-05-18T18:34:47.494+0530","file":"http-server/start.go:65","msg":"Route POST - /v1/{iac}/{iacVersion}/{cloud}/local/file/scan"}
{"level":"info","time":"2021-05-18T18:34:47.494+0530","file":"http-server/start.go:65","msg":"Route POST - /v1/{iac}/{iacVersion}/{cloud}/remote/dir/scan"}
{"level":"info","time":"2021-05-18T18:34:47.494+0530","file":"http-server/start.go:65","msg":"Route GET - /k8s/webhooks/{apiKey}/logs"}
{"level":"info","time":"2021-05-18T18:34:47.494+0530","file":"http-server/start.go:65","msg":"Route GET - /k8s/webhooks/logs/{uid}"}
{"level":"info","time":"2021-05-18T18:34:47.495+0530","file":"http-server/start.go:65","msg":"Route POST - /v1/k8s/webhooks/{apiKey}/scan/validate"}
{"level":"info","time":"2021-05-18T18:34:47.495+0530","file":"http-server/start.go:95","msg":"http server listening at port 9010"}
{"level":"info","time":"2021-05-18T18:34:52.123+0530","file":"logging/logwriter.go:25","msg":"::1 - - \"GET /health HTTP/1.1\" 200 0"}
{"level":"info","time":"2021-05-18T18:34:53.262+0530","file":"logging/logwriter.go:25","msg":"::1 - - \"GET /health HTTP/1.1\" 200 0"}
{"level":"info","time":"2021-05-18T18:34:54.702+0530","file":"logging/logwriter.go:25","msg":"::1 - - \"GET /health HTTP/1.1\" 200 0"}
{"level":"info","time":"2021-05-18T18:35:01.599+0530","file":"logging/logwriter.go:25","msg":"::1 - - \"GET / HTTP/1.1\" 404 0"}
{"level":"info","time":"2021-05-18T18:35:03.543+0530","file":"logging/logwriter.go:25","msg":"::1 - - \"GET / HTTP/1.1\" 404 0"}
{"level":"info","time":"2021-05-18T18:35:10.529+0530","file":"logging/logwriter.go:25","msg":"::1 - - \"GET /health HTTP/1.1\" 200 0"}

codecov · 2021-05-18T13:21:55Z

Codecov Report

Merging #785 (1282b93) into master (fafdda4) will decrease coverage by 0.21%.
The diff coverage is 0.00%.

@@            Coverage Diff             @@
##           master     #785      +/-   ##
==========================================
- Coverage   75.20%   74.99%   -0.22%     
==========================================
  Files         112      113       +1     
  Lines        3453     3463      +10     
==========================================
  Hits         2597     2597              
- Misses        665      675      +10     
  Partials      191      191

Impacted Files	Coverage Δ
pkg/http-server/start.go	`0.00% <0.00%> (ø)`
pkg/utils/http/response.go	`0.00% <0.00%> (ø)`

go.mod

kanchwala-yusuf · 2021-05-19T15:23:07Z

pkg/http-server/start.go

@@ -54,14 +56,20 @@ func (g *APIServer) start(routes []*Route, port, certFile, privateKeyFile string
 		router = mux.NewRouter()            // new router
 	)

+	logWriter := logging.GetLogWriter(logger)


I am wondering, why do we need a separate logwriter? The already created logger won't help in this case?

the logwriter consumes the logger.

logger object doesn't implement the Writer interface. so had to create a logwriter object that does.

pkg/utils/http/response.go

pkg/logging/logwriter.go

kanchwala-yusuf · 2021-05-19T15:24:46Z

pkg/logging/logwriter.go

+	return buf
+}
+
+// WriteRequestLog logs an http(s) request to a write object


Not sure if gorillaHandlers should be a part of the logging package? Looks more like a candiate for http utils.

but its logging :)

the log formatter which is used by the gorilla handler would be only writing http(s) logs. So, I agree with @kanchwala-yusuf.
the log formatter (if required) can be moved.

patilpankaj212 · 2021-05-24T06:39:13Z

pkg/logging/logwriter.go

+// buildCommonLogLine builds a log entry for req in Apache Common Log Format.
+// ts is the timestamp with which the entry should be logged.
+// status and size are used to provide the response HTTP status and size.
+func buildCommonLogLine(req *http.Request, url url.URL, ts time.Time, status int, size int) []byte {


This functions accepts a var of type time.Time but never uses it.

patilpankaj212 · 2021-05-24T06:41:03Z

pkg/http-server/start.go

 	}

+	router.NotFoundHandler = gorillaHandlers.CustomLoggingHandler(logWriter, http.HandlerFunc(httputils.NotFound), logging.WriteRequestLog)


was the sole purpose of using a custom logging handler to remove the timestamp that is logged by the default log formatter provided by gorilla handlers?

nope. its more than that. its apache standard http server log format.

The reason I asked is because, it seems to be the only difference between the default log formatter and the log formatter you have implemented. Can you please check once?
https://github.com/gorilla/handlers/blob/master/logging.go#L144

patilpankaj212 · 2021-05-24T06:44:46Z

pkg/logging/logwriter.go

+	buf = append(buf, ` "`...)
+	buf = append(buf, req.Method...)
+	buf = append(buf, " "...)
+	buf = append(buf, uri...)


since the log writer only logs at the info level, we would end up logging the webhook apikey at info level. Is that expected?

good catch. @kanchwala-yusuf wdyt? would that we severe security threat?

devang-gaur · 2021-05-24T11:16:24Z

Updated the PR as per the reviews. PTAL

sonarcloud · 2021-05-31T12:17:19Z

Kudos, SonarCloud Quality Gate passed!

0 Bugs
0 Vulnerabilities
0 Security Hotspots
0 Code Smells

No Coverage information
0.0% Duplication

devang-gaur · 2021-05-31T12:33:05Z

This is how the logging output looks now.

devang-gaur requested review from patilpankaj212, kanchwala-yusuf and Rchanger May 18, 2021 11:27

devang-gaur force-pushed the logging branch from fe48895 to 88e65c4 Compare May 18, 2021 13:06

devang-gaur changed the title ~~added logging middleware~~ add logging middleware May 18, 2021

devang-gaur changed the title ~~add logging middleware~~ add logging middleware for incoming http(s) requests on server May 18, 2021

devang-gaur changed the title ~~add logging middleware for incoming http(s) requests on server~~ add logging middleware for server May 18, 2021

devang-gaur added this to Review in progress in Main Board May 18, 2021

kanchwala-yusuf suggested changes May 19, 2021

View reviewed changes

patilpankaj212 suggested changes May 24, 2021

View reviewed changes

devang-gaur requested review from patilpankaj212 and kanchwala-yusuf May 24, 2021 11:16

amirbenv removed request for kanchwala-yusuf and Rchanger May 25, 2021 16:53

devang-gaur requested a review from kanchwala-yusuf May 26, 2021 12:01

kanchwala-yusuf previously approved these changes May 31, 2021

View reviewed changes

devang-gaur dismissed kanchwala-yusuf’s stale review via 7f427bc May 31, 2021 12:12

devang-gaur force-pushed the logging branch from 664c960 to 7f427bc Compare May 31, 2021 12:12

devang-gaur added 5 commits May 31, 2021 17:43

added logging middleware

c57b205

fixed validation errors

3312117

addressed pr review comments

98d19b3

addressed more pr review comments

2b9a8e8

addressed more pr review comments

1282b93

devang-gaur force-pushed the logging branch from 7f427bc to 1282b93 Compare May 31, 2021 12:16

patilpankaj212 approved these changes May 31, 2021

View reviewed changes

devang-gaur merged commit 0ed8ef7 into tenable:master May 31, 2021

Main Board automation moved this from Review in progress to Done May 31, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

add logging middleware for server #785

add logging middleware for server #785

devang-gaur commented May 18, 2021

devang-gaur commented May 18, 2021

codecov bot commented May 18, 2021 •

edited

kanchwala-yusuf May 19, 2021

devang-gaur May 20, 2021

kanchwala-yusuf May 19, 2021

devang-gaur May 20, 2021

patilpankaj212 May 24, 2021

patilpankaj212 May 24, 2021

patilpankaj212 May 24, 2021

devang-gaur May 24, 2021

patilpankaj212 May 24, 2021

patilpankaj212 May 24, 2021

devang-gaur May 24, 2021

devang-gaur commented May 24, 2021

sonarcloud bot commented May 31, 2021

devang-gaur commented May 31, 2021

		}

		router.NotFoundHandler = gorillaHandlers.CustomLoggingHandler(logWriter, http.HandlerFunc(httputils.NotFound), logging.WriteRequestLog)

add logging middleware for server #785

add logging middleware for server #785

Conversation

devang-gaur commented May 18, 2021

devang-gaur commented May 18, 2021

codecov bot commented May 18, 2021 • edited

Codecov Report

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

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

devang-gaur commented May 24, 2021

sonarcloud bot commented May 31, 2021

devang-gaur commented May 31, 2021

codecov bot commented May 18, 2021 •

edited