From 7c8bccc0a3da8afc814375ad3c153884a2d31fe2 Mon Sep 17 00:00:00 2001 From: Nathaniel Cook Date: Fri, 10 Jun 2016 10:54:59 -0600 Subject: [PATCH] use CLF for http logs --- CHANGELOG.md | 2 ++ cmd/kapacitord/run/server.go | 2 +- cmd/kapacitord/run/server_helper_test.go | 3 ++ integrations/benchmark_test.go | 2 +- integrations/helpers_test.go | 12 +++++++ integrations/streamer_test.go | 2 +- services/httpd/handler.go | 46 ++++++++++++++---------- services/httpd/logger.go | 21 ++++++----- services/httpd/service.go | 7 ++-- services/logging/service.go | 5 ++- 10 files changed, 70 insertions(+), 32 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 0940db192..3f24f3a42 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,8 @@ ### Features +- [#636](https://github.com/influxdata/kapacitor/pull/636): Change HTTP logs to be in Common Log format. + ### Bugfixes - [#621](https://github.com/influxdata/kapacitor/pull/621): Fix obscure error about single vs double quotes. diff --git a/cmd/kapacitord/run/server.go b/cmd/kapacitord/run/server.go index fd138889f..5bb574d62 100644 --- a/cmd/kapacitord/run/server.go +++ b/cmd/kapacitord/run/server.go @@ -205,7 +205,7 @@ func (s *Server) appendInfluxDBService(c []influxdb.Config, defaultInfluxDB, htt func (s *Server) initHTTPDService(c httpd.Config) { l := s.LogService.NewLogger("[httpd] ", log.LstdFlags) - srv := httpd.NewService(c, l) + srv := httpd.NewService(c, l, s.LogService) srv.Handler.MetaClient = s.MetaClient srv.Handler.PointsWriter = s.TaskMaster diff --git a/cmd/kapacitord/run/server_helper_test.go b/cmd/kapacitord/run/server_helper_test.go index 0f32a18e7..a30165b65 100644 --- a/cmd/kapacitord/run/server_helper_test.go +++ b/cmd/kapacitord/run/server_helper_test.go @@ -208,6 +208,9 @@ type LogService struct{} func (l *LogService) NewLogger(prefix string, flag int) *log.Logger { return wlog.New(os.Stderr, prefix, flag) } +func (l *LogService) NewRawLogger(prefix string, flag int) *log.Logger { + return log.New(os.Stderr, prefix, flag) +} func (l *LogService) NewStaticLevelLogger(prefix string, flag int, level wlog.Level) *log.Logger { return log.New(wlog.NewStaticLevelWriter(os.Stderr, level), prefix, flag) diff --git a/integrations/benchmark_test.go b/integrations/benchmark_test.go index 41c40daea..1cb47caa7 100644 --- a/integrations/benchmark_test.go +++ b/integrations/benchmark_test.go @@ -126,7 +126,7 @@ func Bench(b *testing.B, tasksCount, pointCount int, db, rp, measurement, tickSc // Setup HTTPD service config := httpd.NewConfig() config.BindAddress = ":0" // Choose port dynamically - httpdService := httpd.NewService(config, logService.NewLogger("[http] ", log.LstdFlags)) + httpdService := httpd.NewService(config, logService.NewLogger("[http] ", log.LstdFlags), logService) httpdService.Handler.MetaClient = &kapacitor.NoopMetaClient{} err := httpdService.Open() diff --git a/integrations/helpers_test.go b/integrations/helpers_test.go index 83ca4dc0c..e98ce8f11 100644 --- a/integrations/helpers_test.go +++ b/integrations/helpers_test.go @@ -3,6 +3,7 @@ package integrations import ( "errors" "fmt" + "io" "log" "net/http" "net/http/httptest" @@ -127,6 +128,17 @@ type LogService struct{} func (l *LogService) NewLogger(prefix string, flag int) *log.Logger { return wlog.New(os.Stderr, prefix, flag) } +func (l *LogService) NewRawLogger(prefix string, flag int) *log.Logger { + return log.New(os.Stderr, prefix, flag) +} + +func (l *LogService) NewStaticLevelLogger(prefix string, flag int, level wlog.Level) *log.Logger { + return log.New(wlog.NewStaticLevelWriter(os.Stderr, level), prefix, flag) +} + +func (l *LogService) NewStaticLevelWriter(level wlog.Level) io.Writer { + return wlog.NewStaticLevelWriter(os.Stderr, level) +} type UDFService struct { ListFunc func() []string diff --git a/integrations/streamer_test.go b/integrations/streamer_test.go index 28c37a120..3ca448ff8 100644 --- a/integrations/streamer_test.go +++ b/integrations/streamer_test.go @@ -51,7 +51,7 @@ func init() { // create API server config := httpd.NewConfig() config.BindAddress = ":0" // Choose port dynamically - httpService = httpd.NewService(config, logService.NewLogger("[http] ", log.LstdFlags)) + httpService = httpd.NewService(config, logService.NewLogger("[http] ", log.LstdFlags), logService) err := httpService.Open() if err != nil { panic(err) diff --git a/services/httpd/handler.go b/services/httpd/handler.go index 259c7b4b7..900a6c57a 100644 --- a/services/httpd/handler.go +++ b/services/httpd/handler.go @@ -19,6 +19,7 @@ import ( "github.com/influxdata/influxdb/services/meta" "github.com/influxdata/influxdb/uuid" "github.com/influxdata/kapacitor/client/v1" + "github.com/influxdata/kapacitor/services/logging" "github.com/influxdata/wlog" ) @@ -58,21 +59,32 @@ type Handler struct { WritePoints(database, retentionPolicy string, consistencyLevel models.ConsistencyLevel, points []models.Point) error } - Logger *log.Logger - loggingEnabled bool // Log every HTTP access. - WriteTrace bool // Detailed logging of write path - statMap *expvar.Map + // Normal wlog logger + logger *log.Logger + // Detailed logging of write path + // Uses normal logger + writeTrace bool + + // Common log format logger. + // This logger does not use log levels with wlog. + // Its simply a binary on off from the config. + clfLogger *log.Logger + // Log every HTTP access. + loggingEnabled bool + + statMap *expvar.Map } // NewHandler returns a new instance of handler with routes. -func NewHandler(requireAuthentication, loggingEnabled, writeTrace, allowGzip bool, statMap *expvar.Map, l *log.Logger) *Handler { +func NewHandler(requireAuthentication, loggingEnabled, writeTrace, allowGzip bool, statMap *expvar.Map, l *log.Logger, li logging.Interface) *Handler { h := &Handler{ methodMux: make(map[string]*ServeMux), requireAuthentication: requireAuthentication, allowGzip: allowGzip, - Logger: l, + logger: l, + writeTrace: writeTrace, + clfLogger: li.NewRawLogger("[httpd] ", 0), loggingEnabled: loggingEnabled, - WriteTrace: writeTrace, statMap: statMap, } @@ -251,11 +263,10 @@ func (h *Handler) addRawRoute(r Route) error { handler = cors(handler) handler = requestID(handler) - // Logs are INFO level only enable if we are logging INFOs - if h.loggingEnabled && wlog.LogLevel() <= wlog.INFO { - handler = logging(handler, r.Name, h.Logger) + if h.loggingEnabled { + handler = logHandler(handler, r.Name, h.clfLogger) } - handler = recovery(handler, r.Name, h.Logger) // make sure recovery is always last + handler = recovery(handler, r.Name, h.logger) // make sure recovery is always last mux, ok := h.methodMux[r.Method] if !ok { @@ -368,15 +379,15 @@ func (h *Handler) serveWrite(w http.ResponseWriter, r *http.Request, user *meta. b, err := ioutil.ReadAll(body) if err != nil { - if h.WriteTrace { - h.Logger.Print("E! write handler unable to read bytes from request body") + if h.writeTrace { + h.logger.Print("E! write handler unable to read bytes from request body") } h.writeError(w, influxql.Result{Err: err}, http.StatusBadRequest) return } h.statMap.Add(statWriteRequestBytesReceived, int64(len(b))) - if h.WriteTrace { - h.Logger.Printf("D! write body received by handler: %s", string(b)) + if h.writeTrace { + h.logger.Printf("D! write body received by handler: %s", string(b)) } h.serveWriteLine(w, r, b, user) @@ -612,13 +623,12 @@ func requestID(inner http.Handler) http.Handler { }) } -func logging(inner http.Handler, name string, weblog *log.Logger) http.Handler { +func logHandler(inner http.Handler, name string, weblog *log.Logger) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { start := time.Now() l := &responseLogger{w: w} inner.ServeHTTP(l, r) - logLine := "I! " + buildLogLine(l, r, start) - weblog.Println(logLine) + weblog.Println(buildLogLine(l, r, start)) }) } diff --git a/services/httpd/logger.go b/services/httpd/logger.go index 323301b49..266462904 100644 --- a/services/httpd/logger.go +++ b/services/httpd/logger.go @@ -67,10 +67,13 @@ func redactPassword(r *http.Request) { } } -// Common Log Format: http://en.wikipedia.org/wiki/Common_Log_Format - // buildLogLine creates a common log format -// in addition to the common fields, we also append referrer, user agent and request ID +// in addition to the common fields, we also append referrer, user agent, +// request ID and response time (microseconds) +// ie, in apache mod_log_config terms: +// %h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-agent}i\"" %L %D +// +// Common Log Format: http://en.wikipedia.org/wiki/Common_Log_Format func buildLogLine(l *responseLogger, r *http.Request, start time.Time) string { redactPassword(r) @@ -94,15 +97,17 @@ func buildLogLine(l *responseLogger, r *http.Request, start time.Time) string { "-", detect(username, "-"), fmt.Sprintf("[%s]", start.Format("02/Jan/2006:15:04:05 -0700")), - r.Method, + `"` + r.Method, uri, - r.Proto, + r.Proto + `"`, detect(strconv.Itoa(l.Status()), "-"), strconv.Itoa(l.Size()), - detect(referer, "-"), - detect(userAgent, "-"), + `"` + detect(referer, "-") + `"`, + `"` + detect(userAgent, "-") + `"`, r.Header.Get("Request-Id"), - fmt.Sprintf("%s", time.Since(start)), + // response time, report in microseconds because this is consistent + // with apache's %D parameter in mod_log_config + strconv.FormatInt(time.Since(start).Nanoseconds()/1000, 10), } return strings.Join(fields, " ") diff --git a/services/httpd/service.go b/services/httpd/service.go index 5626d1565..3e55ba560 100644 --- a/services/httpd/service.go +++ b/services/httpd/service.go @@ -10,6 +10,8 @@ import ( "strings" "sync" "time" + + "github.com/influxdata/kapacitor/services/logging" ) type Service struct { @@ -35,7 +37,7 @@ type Service struct { logger *log.Logger } -func NewService(c Config, l *log.Logger) *Service { +func NewService(c Config, l *log.Logger, li logging.Interface) *Service { statMap := &expvar.Map{} statMap.Init() s := &Service{ @@ -51,10 +53,11 @@ func NewService(c Config, l *log.Logger) *Service { c.GZIP, statMap, l, + li, ), logger: l, } - s.Handler.Logger = s.logger + s.Handler.logger = s.logger return s } diff --git a/services/logging/service.go b/services/logging/service.go index 9e3f3b8d3..9cc3b2197 100644 --- a/services/logging/service.go +++ b/services/logging/service.go @@ -12,6 +12,7 @@ import ( // Interface for creating new loggers type Interface interface { NewLogger(prefix string, flag int) *log.Logger + NewRawLogger(prefix string, flag int) *log.Logger NewStaticLevelLogger(prefix string, flag int, l wlog.Level) *log.Logger NewStaticLevelWriter(l wlog.Level) io.Writer } @@ -72,7 +73,9 @@ func (s *Service) Close() error { func (s *Service) NewLogger(prefix string, flag int) *log.Logger { return wlog.New(s.f, prefix, flag) } - +func (s *Service) NewRawLogger(prefix string, flag int) *log.Logger { + return log.New(s.f, prefix, flag) +} func (s *Service) NewStaticLevelLogger(prefix string, flag int, l wlog.Level) *log.Logger { return log.New(wlog.NewStaticLevelWriter(s.f, l), prefix, flag) }