Use CLF for http logs

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.

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

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)

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()

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

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)

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))
 	})
 }
 

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, " ")

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
 }
 

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)
 }