From 1f7cffba1124e7bea92c20316b4e41497a693977 Mon Sep 17 00:00:00 2001 From: Zachary Wasserman Date: Wed, 17 Apr 2019 15:55:31 -0700 Subject: [PATCH] Fix newlines in log output (#2029) Fixes a regression introduced in 2.1.0 in which separate log lines are no longer output separated by a newline. Now log lines in both output plugins will do so. --- server/logging/filesystem.go | 2 ++ server/logging/filesystem_test.go | 19 +++++++++++++------ server/logging/firehose.go | 4 ++++ server/logging/firehose_test.go | 19 ++++++++++++------- server/service/service_osquery.go | 6 ------ server/service/service_test.go | 2 +- 6 files changed, 32 insertions(+), 20 deletions(-) diff --git a/server/logging/filesystem.go b/server/logging/filesystem.go index bb199dfbdb..830cc7c98b 100644 --- a/server/logging/filesystem.go +++ b/server/logging/filesystem.go @@ -61,6 +61,8 @@ type flusher interface { // Write writes the provided logs to the filesystem func (l *filesystemLogWriter) Write(logs []json.RawMessage) error { for _, log := range logs { + // Add newline to separate logs in output file + log = append(log, '\n') if _, err := l.writer.Write(log); err != nil { return errors.Wrap(err, "writing log") } diff --git a/server/logging/filesystem_test.go b/server/logging/filesystem_test.go index 982755d958..ee1a27311d 100644 --- a/server/logging/filesystem_test.go +++ b/server/logging/filesystem_test.go @@ -13,7 +13,7 @@ import ( "github.com/stretchr/testify/require" ) -func TestLogger(t *testing.T) { +func TestFilesystemLogger(t *testing.T) { tempPath, err := ioutil.TempDir("", "test") require.Nil(t, err) fileName := path.Join(tempPath, "filesystemLogWriter") @@ -21,14 +21,20 @@ func TestLogger(t *testing.T) { require.Nil(t, err) defer os.Remove(fileName) + var ( + batches = 50 + logCount = 100 + logSize = 512 + ) + var logs []json.RawMessage - for i := 0; i < 50; i++ { - randInput := make([]byte, 512) + for i := 0; i < logCount; i++ { + randInput := make([]byte, logSize) rand.Read(randInput) logs = append(logs, randInput) } - for i := 0; i < 100; i++ { + for i := 0; i < batches; i++ { err := lgr.Write(logs) require.Nil(t, err) } @@ -46,11 +52,12 @@ func TestLogger(t *testing.T) { info, err := os.Stat(fileName) require.Nil(t, err) - assert.Equal(t, int64(512*50*100), info.Size()) + // + 1 below is for newlines that should be appended to each log + assert.Equal(t, int64(batches*logCount*(logSize+1)), info.Size()) } -func BenchmarkLogger(b *testing.B) { +func BenchmarkFilesystemLogger(b *testing.B) { tempPath, err := ioutil.TempDir("", "test") if err != nil { b.Fatal("temp dir failed", err) diff --git a/server/logging/firehose.go b/server/logging/firehose.go index 4ff4d1efb2..968bf3e04f 100644 --- a/server/logging/firehose.go +++ b/server/logging/firehose.go @@ -75,6 +75,10 @@ func (f *firehoseLogWriter) Write(logs []json.RawMessage) error { var records []*firehose.Record totalBytes := 0 for _, log := range logs { + // Add newline because Firehose does not output each record on + // a separate line. + log = append(log, '\n') + // We don't really have a good option for what to do with logs // that are too big for Firehose. This behavior is consistent // with osquery's behavior in the Firehose logger plugin, and diff --git a/server/logging/firehose_test.go b/server/logging/firehose_test.go index d04a39b1e9..900e447be1 100644 --- a/server/logging/firehose_test.go +++ b/server/logging/firehose_test.go @@ -20,6 +20,11 @@ var ( json.RawMessage(`{"flim": "flam"}`), json.RawMessage(`{"jim": "jom"}`), } + logsWithNewlines = []json.RawMessage{ + json.RawMessage(`{"foo": "bar"}` + "\n"), + json.RawMessage(`{"flim": "flam"}` + "\n"), + json.RawMessage(`{"jim": "jom"}` + "\n"), + } ) func makeFirehoseWriterWithMock(client firehoseiface.FirehoseAPI, stream string) *firehoseLogWriter { @@ -55,7 +60,7 @@ func TestFirehoseRetryableFailure(t *testing.T) { callCount := 0 putFunc := func(input *firehose.PutRecordBatchInput) (*firehose.PutRecordBatchOutput, error) { callCount += 1 - assert.Equal(t, logs, getLogsFromInput(input)) + assert.Equal(t, logsWithNewlines, getLogsFromInput(input)) assert.Equal(t, "foobar", *input.DeliveryStreamName) if callCount < 3 { return nil, awserr.New(firehose.ErrCodeServiceUnavailableException, "", nil) @@ -76,7 +81,7 @@ func TestFirehoseNormalPut(t *testing.T) { callCount := 0 putFunc := func(input *firehose.PutRecordBatchInput) (*firehose.PutRecordBatchOutput, error) { callCount += 1 - assert.Equal(t, logs, getLogsFromInput(input)) + assert.Equal(t, logsWithNewlines, getLogsFromInput(input)) assert.Equal(t, "foobar", *input.DeliveryStreamName) return &firehose.PutRecordBatchOutput{FailedPutCount: aws.Int64(0)}, nil } @@ -94,7 +99,7 @@ func TestFirehoseSomeFailures(t *testing.T) { call3 := func(input *firehose.PutRecordBatchInput) (*firehose.PutRecordBatchOutput, error) { // final invocation callCount += 1 - assert.Equal(t, logs[1:2], getLogsFromInput(input)) + assert.Equal(t, logsWithNewlines[1:2], getLogsFromInput(input)) return &firehose.PutRecordBatchOutput{ FailedPutCount: aws.Int64(0), }, nil @@ -104,7 +109,7 @@ func TestFirehoseSomeFailures(t *testing.T) { // Set to invoke call3 next time f.PutRecordBatchFunc = call3 callCount += 1 - assert.Equal(t, logs[1:], getLogsFromInput(input)) + assert.Equal(t, logsWithNewlines[1:], getLogsFromInput(input)) return &firehose.PutRecordBatchOutput{ FailedPutCount: aws.Int64(1), RequestResponses: []*firehose.PutRecordBatchResponseEntry{ @@ -122,7 +127,7 @@ func TestFirehoseSomeFailures(t *testing.T) { // Use call2 function for next call f.PutRecordBatchFunc = call2 callCount += 1 - assert.Equal(t, logs, getLogsFromInput(input)) + assert.Equal(t, logsWithNewlines, getLogsFromInput(input)) return &firehose.PutRecordBatchOutput{ FailedPutCount: aws.Int64(1), RequestResponses: []*firehose.PutRecordBatchResponseEntry{ @@ -151,7 +156,7 @@ func TestFirehoseFailAllRecords(t *testing.T) { f.PutRecordBatchFunc = func(input *firehose.PutRecordBatchInput) (*firehose.PutRecordBatchOutput, error) { callCount += 1 - assert.Equal(t, logs, getLogsFromInput(input)) + assert.Equal(t, logsWithNewlines, getLogsFromInput(input)) if callCount < 3 { return &firehose.PutRecordBatchOutput{ FailedPutCount: aws.Int64(1), @@ -187,7 +192,7 @@ func TestFirehoseRecordTooBig(t *testing.T) { callCount := 0 putFunc := func(input *firehose.PutRecordBatchInput) (*firehose.PutRecordBatchOutput, error) { callCount += 1 - assert.Equal(t, logs[1:], getLogsFromInput(input)) + assert.Equal(t, logsWithNewlines[1:], getLogsFromInput(input)) assert.Equal(t, "foobar", *input.DeliveryStreamName) return &firehose.PutRecordBatchOutput{FailedPutCount: aws.Int64(0)}, nil } diff --git a/server/service/service_osquery.go b/server/service/service_osquery.go index 80e23407e9..b112b461c4 100644 --- a/server/service/service_osquery.go +++ b/server/service/service_osquery.go @@ -191,9 +191,6 @@ func (svc service) GetClientConfig(ctx context.Context) (map[string]interface{}, } func (svc service) SubmitStatusLogs(ctx context.Context, logs []json.RawMessage) error { - for _, log := range logs { - log = append(log, '\n') - } if err := svc.osqueryLogWriter.Status.Write(logs); err != nil { return osqueryError{message: "error writing status logs: " + err.Error()} } @@ -201,9 +198,6 @@ func (svc service) SubmitStatusLogs(ctx context.Context, logs []json.RawMessage) } func (svc service) SubmitResultLogs(ctx context.Context, logs []json.RawMessage) error { - for _, log := range logs { - log = append(log, '\n') - } if err := svc.osqueryLogWriter.Result.Write(logs); err != nil { return osqueryError{message: "error writing result logs: " + err.Error()} } diff --git a/server/service/service_test.go b/server/service/service_test.go index ff99197110..f91f4ec964 100644 --- a/server/service/service_test.go +++ b/server/service/service_test.go @@ -46,5 +46,5 @@ func TestRotateLoggerSIGHUP(t *testing.T) { logMsg, err := ioutil.ReadFile(f.Name()) require.Nil(t, err) - require.Equal(t, "msg2", string(logMsg)) + require.Equal(t, "msg2\n", string(logMsg)) }