Changed default osquery logging behavior

Made log rotation for osquery results and status logs optional.  This required writing the logwriter package which is a drop in replacement for lumberjack.  We still use lumberjack if the log rotation flag --osquery_enable_log_rotation flag is set. Note that the performance of the default is quite a bit better than lumberjack.


BenchmarkLogger-8       	 2000000	       747 ns/op
BenchmarkLumberjack-8   	 1000000	      1965 ns/op
PASS
BenchmarkLogger-8       	 2000000	       731 ns/op
BenchmarkLumberjack-8   	 1000000	      2040 ns/op
PASS
BenchmarkLogger-8       	 2000000	       741 ns/op
BenchmarkLumberjack-8   	 1000000	      1970 ns/op
PASS
BenchmarkLogger-8       	 2000000	       737 ns/op
BenchmarkLumberjack-8   	 1000000	      1930 ns/op
PASS

CHANGELOG.md

@@ -1,3 +1,7 @@
+## Kolide 1.0.2 (April 3, 2017)
+
+* Log rotation is no longer the default setting for Osquery status and results logs. To enable log rotation use the `--osquery_enable_log_rotation` flag.
+
 * Add a debug endpoint for collecting performance statistics and profiles.
 
   When `kolide serve --debug` is used, additional handlers will be started to provide access to profiling tools. These endpoints are authenticated with a randomly generated token that is printed to the Kolide logs at startup. These profiling tools are not intended for general use, but they may be useful when providing performance-related bug reports to the Kolide developers.

docs/infrastructure/configuring-the-kolide-binary.md

@@ -473,6 +473,20 @@ The interval at which Kolide will ask osquery agents to update their results for
 		label_query_update_interval: 30m
 	```
 
+##### `osquery_enable_log_rotation`
+
+This flag will cause the osquery result and status log files to be automatically
+rotated when files reach a size of 500 Mb or an age of 28 days.
+
+- Default value: `false`
+- Environment variable: `KOLIDE_OSQUERY_ENABLE_LOG_ROTATION`
+- Config file format:
+
+  ```
+  osquery:
+     enable_log_rotation: true
+  ```
+
 #### Logging
 
 ##### `logging_debug`
@@ -513,5 +527,3 @@ Whether or not to log the welcome banner.
 	logging:
 		diable_banner: true
 	```
-
-

server/config/config.go

@@ -74,6 +74,7 @@ type OsqueryConfig struct {
 	NodeKeySize         int           `yaml:"node_key_size"`
 	StatusLogFile       string        `yaml:"status_log_file"`
 	ResultLogFile       string        `yaml:"result_log_file"`
+	EnableLogRotation   bool          `yaml:"enable_log_rotation"`
 	LabelUpdateInterval time.Duration `yaml:"label_update_interval"`
 }
 
@@ -172,6 +173,8 @@ func (man Manager) addConfigs() {
 		"Path for osqueryd result logs")
 	man.addConfigDuration("osquery.label_update_interval", 1*time.Hour,
 		"Interval to update host label membership (i.e. 1h)")
+	man.addConfigBool("osquery.enable_log_rotation", false,
+		"Osquery log files will be automatically rotated")
 
 	// Logging
 	man.addConfigBool("logging.debug", false,
@@ -229,6 +232,7 @@ func (man Manager) LoadConfig() KolideConfig {
 			StatusLogFile:       man.getConfigString("osquery.status_log_file"),
 			ResultLogFile:       man.getConfigString("osquery.result_log_file"),
 			LabelUpdateInterval: man.getConfigDuration("osquery.label_update_interval"),
+			EnableLogRotation:   man.getConfigBool("osquery.enable_log_rotation"),
 		},
 		Logging: LoggingConfig{
 			Debug:         man.getConfigBool("logging.debug"),
@@ -449,8 +453,8 @@ func TestConfig() KolideConfig {
 		},
 		Osquery: OsqueryConfig{
 			NodeKeySize:         24,
-			StatusLogFile:       "",
-			ResultLogFile:       "",
+			StatusLogFile:       "/dev/null",
+			ResultLogFile:       "/dev/null",
 			LabelUpdateInterval: 1 * time.Hour,
 		},
 		Logging: LoggingConfig{

server/logwriter/logwriter.go

@@ -0,0 +1,66 @@
+// Package logwriter provides logging utilities for writing osquery results and status logs
+package logwriter
+
+import (
+	"bufio"
+	"errors"
+	"io"
+	"os"
+	"sync"
+)
+
+type logWriter struct {
+	file *os.File
+	buff *bufio.Writer
+	mtx  sync.Mutex
+}
+
+// New creates a logwriter, path refers to file that will recieve log content
+func New(path string) (io.WriteCloser, error) {
+	file, err := os.OpenFile(path, os.O_WRONLY|os.O_APPEND|os.O_CREATE, 0644)
+	if err != nil {
+		return nil, err
+	}
+	buff := bufio.NewWriter(file)
+	return &logWriter{file: file, buff: buff}, nil
+}
+
+// Write bytes to file
+func (l *logWriter) Write(b []byte) (int, error) {
+	l.mtx.Lock()
+	defer l.mtx.Unlock()
+	if l.buff == nil {
+		return 0, errors.New("can't write to a closed file")
+	}
+	return l.buff.Write(b)
+}
+
+// Flush write all buffered bytes to log file
+func (l *logWriter) Flush() error {
+	l.mtx.Lock()
+	defer l.mtx.Unlock()
+	if l.buff == nil {
+		return errors.New("can't write to a closed file")
+	}
+	return l.buff.Flush()
+}
+
+// Close log file
+func (l *logWriter) Close() error {
+	l.mtx.Lock()
+	defer l.mtx.Unlock()
+	if l.buff != nil {
+		if err := l.buff.Flush(); err != nil {
+			return err
+		}
+		l.buff = nil
+	}
+	if l.file != nil {
+		if err := l.file.Close(); err != nil {
+			return err
+		}
+		l.file = nil
+	}
+
+	return nil
+}

server/logwriter/logwriter_test.go

@@ -0,0 +1,111 @@
+package logwriter
+
+import (
+	"crypto/rand"
+	"io/ioutil"
+	"os"
+	"path"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	lumberjack "gopkg.in/natefinch/lumberjack.v2"
+)
+
+func TestLogger(t *testing.T) {
+	tempPath, err := ioutil.TempDir("", "test")
+	require.Nil(t, err)
+	fileName := path.Join(tempPath, "logwriter")
+	lgr, err := New(fileName)
+	require.Nil(t, err)
+	defer os.Remove(fileName)
+
+	randInput := make([]byte, 512)
+	rand.Read(randInput)
+
+	for i := 0; i < 100; i++ {
+		n, err := lgr.Write(randInput)
+		require.Nil(t, err)
+		assert.Equal(t, 512, n)
+	}
+
+	err = lgr.Close()
+	assert.Nil(t, err)
+
+	// can't write to a closed logger
+	_, err = lgr.Write(randInput)
+	assert.NotNil(t, err)
+
+	// call close twice noop
+	err = lgr.Close()
+	assert.Nil(t, err)
+
+	info, err := os.Stat(fileName)
+	require.Nil(t, err)
+	assert.Equal(t, int64(51200), info.Size())
+
+}
+
+func BenchmarkLogger(b *testing.B) {
+	tempPath, err := ioutil.TempDir("", "test")
+	if err != nil {
+		b.Fatal("temp dir failed", err)
+	}
+	fileName := path.Join(tempPath, "logwriter")
+	lgr, err := New(fileName)
+	if err != nil {
+		b.Fatal("new failed ", err)
+	}
+	defer os.Remove(fileName)
+
+	randInput := make([]byte, 512)
+	rand.Read(randInput)
+	b.ResetTimer()
+
+	for i := 0; i < b.N; i++ {
+		_, err := lgr.Write(randInput)
+		if err != nil {
+			b.Fatal("write failed ", err)
+		}
+	}
+
+	b.StopTimer()
+
+	lgr.Close()
+}
+
+func BenchmarkLumberjack(b *testing.B) {
+	tempPath, err := ioutil.TempDir("", "test")
+	if err != nil {
+		b.Fatal("temp dir failed", err)
+	}
+	fileName := path.Join(tempPath, "lumberjack")
+	lgr := &lumberjack.Logger{
+		Filename:   fileName,
+		MaxSize:    500, // megabytes
+		MaxBackups: 3,
+		MaxAge:     28, //days
+	}
+	defer os.Remove(fileName)
+
+	randInput := make([]byte, 512)
+	rand.Read(randInput)
+	// first lumberjack write opens file so we count that as part of initialization
+	// just to make sure we're comparing apples to apples with our logger
+	_, err = lgr.Write(randInput)
+	if err != nil {
+		b.Fatal("first write failed ", err)
+	}
+	b.ResetTimer()
+
+	for i := 0; i < b.N; i++ {
+		_, err := lgr.Write(randInput)
+		if err != nil {
+			b.Fatal("write failed ", err)
+		}
+	}
+
+	b.StopTimer()
+
+	lgr.Close()
+}

server/service/service.go

@@ -12,15 +12,21 @@ import (
 	kitlog "github.com/go-kit/kit/log"
 	"github.com/kolide/kolide/server/config"
 	"github.com/kolide/kolide/server/kolide"
+	"github.com/kolide/kolide/server/logwriter"
 	lumberjack "gopkg.in/natefinch/lumberjack.v2"
 )
 
 // NewService creates a new service from the config struct
 func NewService(ds kolide.Datastore, resultStore kolide.QueryResultStore, logger kitlog.Logger, kolideConfig config.KolideConfig, mailService kolide.MailService, c clock.Clock, checker kolide.LicenseChecker) (kolide.Service, error) {
 	var svc kolide.Service
-
-	statusWriter := osqueryLogFile(kolideConfig.Osquery.StatusLogFile, logger)
-	resultWriter := osqueryLogFile(kolideConfig.Osquery.ResultLogFile, logger)
+	statusWriter, err := osqueryLogFile(kolideConfig.Osquery.StatusLogFile, logger, kolideConfig.Osquery.EnableLogRotation)
+	if err != nil {
+		return nil, err
+	}
+	resultWriter, err := osqueryLogFile(kolideConfig.Osquery.ResultLogFile, logger, kolideConfig.Osquery.EnableLogRotation)
+	if err != nil {
+		return nil, err
+	}
 
 	svc = service{
 		ds:             ds,
@@ -39,28 +45,31 @@ func NewService(ds kolide.Datastore, resultStore kolide.QueryResultStore, logger
 }
 
 // osqueryLogFile creates a log file for osquery status/result logs
-// the logFile can be rotated by sending a `SIGHUP` signal to kolide.
-func osqueryLogFile(path string, appLogger kitlog.Logger) io.Writer {
-	osquerydLogger := &lumberjack.Logger{
-		Filename:   path,
-		MaxSize:    500, // megabytes
-		MaxBackups: 3,
-		MaxAge:     28, //days
-	}
-	appLogger = kitlog.With(appLogger, "component", "osqueryd-logger")
-
-	sig := make(chan os.Signal)
-	signal.Notify(sig, syscall.SIGHUP)
-	go func() {
-		for {
-			<-sig //block on signal
-			if err := osquerydLogger.Rotate(); err != nil {
-				appLogger.Log("err", err)
-			}
+// the logFile can be rotated by sending a `SIGHUP` signal to kolide if
+// enableRotation is true
+func osqueryLogFile(path string, appLogger kitlog.Logger, enableRotation bool) (io.Writer, error) {
+	if enableRotation {
+		osquerydLogger := &lumberjack.Logger{
+			Filename:   path,
+			MaxSize:    500, // megabytes
+			MaxBackups: 3,
+			MaxAge:     28, //days
 		}
-	}()
-
-	return osquerydLogger
+		appLogger = kitlog.With(appLogger, "component", "osqueryd-logger")
+		sig := make(chan os.Signal)
+		signal.Notify(sig, syscall.SIGHUP)
+		go func() {
+			for {
+				<-sig //block on signal
+				if err := osquerydLogger.Rotate(); err != nil {
+					appLogger.Log("err", err)
+				}
+			}
+		}()
+		return osquerydLogger, nil
+	}
+	// no log rotation
+	return logwriter.New(path)
 }
 
 type service struct {

server/service/service_osquery.go

@@ -151,6 +151,12 @@ func (svc service) GetClientConfig(ctx context.Context) (*kolide.OsqueryConfig,
 	return config, nil
 }
 
+// If osqueryWriters are based on bufio we want to flush after a batch of
+// writes so log entry gets completely written to the logfile.
+type flusher interface {
+	Flush() error
+}
+
 func (svc service) SubmitStatusLogs(ctx context.Context, logs []kolide.OsqueryStatusLog) error {
 	for _, log := range logs {
 		err := json.NewEncoder(svc.osqueryStatusLogWriter).Encode(log)
@@ -158,7 +164,12 @@ func (svc service) SubmitStatusLogs(ctx context.Context, logs []kolide.OsquerySt
 			return osqueryError{message: "error writing status log: " + err.Error()}
 		}
 	}
-
+	if writer, ok := svc.osqueryStatusLogWriter.(flusher); ok {
+		err := writer.Flush()
+		if err != nil {
+			return osqueryError{message: "error flushing status log: " + err.Error()}
+		}
+	}
 	return nil
 }
 
@@ -169,7 +180,12 @@ func (svc service) SubmitResultLogs(ctx context.Context, logs []kolide.OsqueryRe
 			return osqueryError{message: "error writing result log: " + err.Error()}
 		}
 	}
-
+	if writer, ok := svc.osqueryResultLogWriter.(flusher); ok {
+		err := writer.Flush()
+		if err != nil {
+			return osqueryError{message: "error flushing status log: " + err.Error()}
+		}
+	}
 	return nil
 }
 

server/service/service_osquery_test.go

@@ -5,6 +5,7 @@ import (
 	"context"
 	"encoding/json"
 	"fmt"
+	"io"
 	"strings"
 	"sync"
 	"testing"
@@ -84,6 +85,12 @@ func TestAuthenticateHost(t *testing.T) {
 	assert.Equal(t, mockClock.Now(), checkHost.UpdatedAt)
 }
 
+type nopCloserWriter struct {
+	io.Writer
+}
+
+func (n *nopCloserWriter) Close() error { return nil }
+
 func TestSubmitStatusLogs(t *testing.T) {
 	ds, svc, _ := setupOsqueryTests(t)
 	ctx := context.Background()
@@ -101,7 +108,7 @@ func TestSubmitStatusLogs(t *testing.T) {
 	serv := ((svc.(validationMiddleware)).Service).(service)
 
 	var statusBuf bytes.Buffer
-	serv.osqueryStatusLogWriter = &statusBuf
+	serv.osqueryStatusLogWriter = &nopCloserWriter{&statusBuf}
 
 	logs := []string{
 		`{"severity":"0","filename":"tls.cpp","line":"216","message":"some message","version":"1.8.2","decorations":{"host_uuid":"uuid_foobar","username":"zwass"}}`,
@@ -144,7 +151,7 @@ func TestSubmitResultLogs(t *testing.T) {
 	serv := ((svc.(validationMiddleware)).Service).(service)
 
 	var resultBuf bytes.Buffer
-	serv.osqueryResultLogWriter = &resultBuf
+	serv.osqueryResultLogWriter = &nopCloserWriter{&resultBuf}
 
 	logs := []string{
 		`{"name":"system_info","hostIdentifier":"some_uuid","calendarTime":"Fri Sep 30 17:55:15 2016 UTC","unixTime":"1475258115","decorations":{"host_uuid":"some_uuid","username":"zwass"},"columns":{"cpu_brand":"Intel(R) Core(TM) i7-4770HQ CPU @ 2.20GHz","hostname":"hostimus","physical_memory":"17179869184"},"action":"added"}`,

server/service/service_test.go

@@ -21,7 +21,8 @@ func TestRotateLoggerSIGHUP(t *testing.T) {
 	require.Nil(t, err)
 	defer f.Close()
 
-	logFile := osqueryLogFile(f.Name(), log.NewNopLogger())
+	logFile, err := osqueryLogFile(f.Name(), log.NewNopLogger(), false)
+	require.Nil(t, err)
 
 	// write a log line
 	logFile.Write([]byte("msg1"))