luciano/amazon-kinesis-client-go
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions
amazon-kinesis-client-go/decode/decode_test.go
Taylor Sutton f5ce6fe4e7 Add decoding of JSON logs in Fluent format. 
ParseAndEnhance used to be:
- Try to parse line as a syslog, extracting the log itself and other
  fields from syslog format
  - If that succeeds, try to parse the log as either a Kayvee log or
    an RDS slow query log.
  - Combine all these fields, and add on some "derived"
    fields (container_task|env|app).
- Not a syslog => error

Now it will be:
- Try to parse line as a syslog, same as before, including the
  Kayvee/RDS part
- If syslog parsing failed, try to parse as a Fluent log and extract
  some fields from the Fluent format (the log, timestamp, etc)
  - If that succeeds, try to parse the log itself as a Kayvee log.
  - Combine Kayvee fields (if found) and derived fields)
- If BOTH formats fields, it is an error.

The decoding makes a lot of assumptions:
- The names of the log field and timestamp field (even though,
theoretically, they are customizable in the fluentbit config.
- The timestamp format (again)
- The format of the Task Definition name (or at least part of it)
- All fluentbit logs should have hostname set to `aws-fargate`.

Perhaps these can be relaxed if necessary. They could probably be
replaced by some kind of config. As there is currently no config I
wanted to keep things simple as possible. If we need to re-evaluate
(for example if we start getting JSON logs that don't want to use the
same handling for container_task|env|app) we can reevaluate.
2020-08-17 15:02:59 -07:00

1019 lines
36 KiB
Go
Raw Blame History

package decode
import (
"errors"
"fmt"
"sort"
"testing"
"time"
"github.com/Clever/syslogparser"
"github.com/stretchr/testify/assert"
)
const RFC3339Micro = "2006-01-02T15:04:05.999999-07:00"
type Spec struct {
Title string
Input string
ExpectedOutput map[string]interface{}
ExpectedError error
}
func TestKayveeDecoding(t *testing.T) {
specs := []Spec{
Spec{
Title: "handles just JSON",
Input: `{"a":"b"}`,
ExpectedOutput: map[string]interface{}{
"prefix": "",
"postfix": "",
"a": "b",
"decoder_msg_type": "Kayvee",
},
ExpectedError: nil,
},
Spec{
Title: "handles prefix + JSON",
Input: `prefix {"a":"b"}`,
ExpectedOutput: map[string]interface{}{
"prefix": "prefix ",
"postfix": "",
"a": "b",
"decoder_msg_type": "Kayvee",
},
ExpectedError: nil,
},
Spec{
Title: "handles JSON + postfix",
Input: `{"a":"b"} postfix`,
ExpectedOutput: map[string]interface{}{
"prefix": "",
"postfix": " postfix",
"a": "b",
"decoder_msg_type": "Kayvee",
},
ExpectedError: nil,
},
Spec{
Title: "handles prefix + JSON + postfix",
Input: `prefix {"a":"b"} postfix`,
ExpectedOutput: map[string]interface{}{
"prefix": "prefix ",
"postfix": " postfix",
"a": "b",
"decoder_msg_type": "Kayvee",
},
ExpectedError: nil,
},
Spec{
Title: "Reserved fields are respected",
Input: `prefix {"a":"b","prefix":"no-override","postfix":"no-override",` +
`"decoder_msg_type":"no-override","timestamp":"no-override",` +
`"hostname":"no-override","rawlog":"no-override"} postfix`,
ExpectedOutput: map[string]interface{}{
"prefix": "prefix ",
"postfix": " postfix",
"a": "b",
"decoder_msg_type": "Kayvee",
},
ExpectedError: nil,
},
Spec{
Title: "Returns NonKayveeError if not JSON in body",
Input: `prefix { postfix`,
ExpectedOutput: map[string]interface{}{},
ExpectedError: &NonKayveeError{},
},
Spec{
Title: "errors on invalid JSON (missing a quote)",
Input: `prefix {"a:"b"} postfix`,
ExpectedOutput: map[string]interface{}{},
ExpectedError: &NonKayveeError{},
},
Spec{
Title: "errors on empty JSON: {}",
Input: `prefix {} postfix`,
ExpectedOutput: map[string]interface{}{},
ExpectedError: &NonKayveeError{},
},
}
for _, spec := range specs {
t.Run(fmt.Sprintf(spec.Title), func(t *testing.T) {
assert := assert.New(t)
fields, err := FieldsFromKayvee(spec.Input)
if spec.ExpectedError != nil {
assert.Error(err)
assert.IsType(spec.ExpectedError, err)
} else {
assert.NoError(err)
}
assert.Equal(spec.ExpectedOutput, fields)
})
}
}
func TestSyslogDecoding(t *testing.T) {
// timestamps in Rsyslog_TraditionalFileFormat
logTime, err := time.Parse(time.Stamp, "Oct 25 10:20:37")
if err != nil {
t.Fatal(err)
}
// parsing assumes log is from the current year
logTime = logTime.AddDate(time.Now().Year(), 0, 0).UTC()
logTime2, err := time.Parse(time.Stamp, "Apr 5 21:45:54")
if err != nil {
t.Fatal(err)
}
logTime2 = logTime2.AddDate(time.Now().Year(), 0, 0).UTC()
// timestamp in Rsyslog_FileFormat
logTime3, err := time.Parse(RFC3339Micro, "2017-04-05T21:57:46.794862+00:00")
if err != nil {
t.Fatal(err)
}
logTime3 = logTime3.UTC()
specs := []Spec{
Spec{
Title: "Parses Rsyslog_TraditionalFileFormat with simple log body",
Input: `Oct 25 10:20:37 some-host docker/fa3a5e338a47[1294]: log body`,
ExpectedOutput: map[string]interface{}{
"timestamp": logTime,
"hostname": "some-host",
"programname": "docker/fa3a5e338a47",
"rawlog": "log body",
"decoder_msg_type": "syslog",
},
ExpectedError: nil,
},
Spec{
Title: "Parses Rsyslog_TraditionalFileFormat with haproxy access log body",
Input: `Apr 5 21:45:54 influx-service docker/0000aa112233[1234]: [httpd] 2017/04/05 21:45:54 172.17.42.1 - heka [05/Apr/2017:21:45:54 +0000] POST /write?db=foo&precision=ms HTTP/1.1 204 0 - Go 1.1 package http 123456-1234-1234-b11b-000000000000 13.688672ms`,
ExpectedOutput: map[string]interface{}{
"timestamp": logTime2,
"hostname": "influx-service",
"programname": "docker/0000aa112233",
"rawlog": "[httpd] 2017/04/05 21:45:54 172.17.42.1 - heka [05/Apr/2017:21:45:54 +0000] POST /write?db=foo&precision=ms HTTP/1.1 204 0 - Go 1.1 package http 123456-1234-1234-b11b-000000000000 13.688672ms",
"decoder_msg_type": "syslog",
},
ExpectedError: nil,
},
Spec{
Title: "Parses Rsyslog_TraditionalFileFormat",
Input: `Apr 5 21:45:54 mongodb-some-machine whackanop: 2017/04/05 21:46:11 found 0 ops`,
ExpectedOutput: map[string]interface{}{
"timestamp": logTime2,
"hostname": "mongodb-some-machine",
"programname": "whackanop",
"rawlog": "2017/04/05 21:46:11 found 0 ops",
"decoder_msg_type": "syslog",
},
ExpectedError: nil,
},
Spec{
Title: "Parses Rsyslog_ FileFormat with Kayvee payload",
Input: `2017-04-05T21:57:46.794862+00:00 ip-10-0-0-0 env--app/arn%3Aaws%3Aecs%3Aus-west-1%3A999988887777%3Atask%2Fabcd1234-1a3b-1a3b-1234-d76552f4b7ef[3291]: 2017/04/05 21:57:46 some_file.go:10: {"title":"request_finished"}`,
ExpectedOutput: map[string]interface{}{
"timestamp": logTime3,
"hostname": "ip-10-0-0-0",
"programname": `env--app/arn%3Aaws%3Aecs%3Aus-west-1%3A999988887777%3Atask%2Fabcd1234-1a3b-1a3b-1234-d76552f4b7ef`,
"rawlog": `2017/04/05 21:57:46 some_file.go:10: {"title":"request_finished"}`,
"decoder_msg_type": "syslog",
},
ExpectedError: nil,
},
Spec{
Title: "Parses Rsyslog_ FileFormat without PID",
Input: `2017-04-05T21:57:46.794862+00:00 ip-10-0-0-0 env--app/arn%3Aaws%3Aecs%3Aus-west-1%3A999988887777%3Atask%2Fabcd1234-1a3b-1a3b-1234-d76552f4b7ef: 2017/04/05 21:57:46 some_file.go:10: {"title":"request_finished"}`,
ExpectedOutput: map[string]interface{}{
"timestamp": logTime3,
"hostname": "ip-10-0-0-0",
"programname": `env--app/arn%3Aaws%3Aecs%3Aus-west-1%3A999988887777%3Atask%2Fabcd1234-1a3b-1a3b-1234-d76552f4b7ef`,
"rawlog": `2017/04/05 21:57:46 some_file.go:10: {"title":"request_finished"}`,
"decoder_msg_type": "syslog",
},
ExpectedError: nil,
},
Spec{
Title: "Parses Rsyslog_ FileFormat with simple log body for slowquery",
Input: `2017-04-05T21:57:46.794862+00:00 aws-rds production-aurora-test-db: Slow query: select * from table.`,
ExpectedOutput: map[string]interface{}{
"timestamp": logTime3,
"hostname": "aws-rds",
"programname": "production-aurora-test-db",
"rawlog": "Slow query: select * from table.",
"decoder_msg_type": "syslog",
},
ExpectedError: nil,
},
Spec{
Title: "Fails to parse non-RSyslog log line",
Input: `not rsyslog`,
ExpectedOutput: map[string]interface{}{},
ExpectedError: &syslogparser.ParserError{},
},
}
for _, spec := range specs {
t.Run(fmt.Sprintf(spec.Title), func(t *testing.T) {
assert := assert.New(t)
fields, err := FieldsFromSyslog(spec.Input)
if spec.ExpectedError != nil {
assert.Error(err)
assert.True(errors.As(err, &spec.ExpectedError))
return
}
assert.NoError(err)
assert.Equal(spec.ExpectedOutput, fields)
})
}
}
type ParseAndEnhanceSpec struct {
Title string
Line string
ExpectedOutput map[string]interface{}
ExpectedError error
}
func TestParseAndEnhance(t *testing.T) {
logTime2, err := time.Parse(time.RFC3339, "2017-04-05T21:57:46+00:00")
if err != nil {
t.Fatal(err)
}
logTime2 = logTime2.UTC()
// timestamp in Rsyslog_FileFormat
logTime3, err := time.Parse(RFC3339Micro, "2017-04-05T21:57:46.794862+00:00")
if err != nil {
t.Fatal(err)
}
logTime3 = logTime3.UTC()
logTime4, err := time.Parse(fluentTimeFormat, "2020-08-13T21:10:57.000+0000")
if err != nil {
t.Fatal(err)
}
specs := []ParseAndEnhanceSpec{
ParseAndEnhanceSpec{
Title: "Parses a Kayvee log line from an ECS app",
Line: `2017-04-05T21:57:46.794862+00:00 ip-10-0-0-0 env--app/arn%3Aaws%3Aecs%3Aus-west-1%3A999988887777%3Atask%2Fabcd1234-1a3b-1a3b-1234-d76552f4b7ef[3291]: 2017/04/05 21:57:46 some_file.go:10: {"title":"request_finished"}`,
ExpectedOutput: map[string]interface{}{
"timestamp": logTime3,
"hostname": "ip-10-0-0-0",
"programname": `env--app/arn%3Aaws%3Aecs%3Aus-west-1%3A999988887777%3Atask%2Fabcd1234-1a3b-1a3b-1234-d76552f4b7ef`,
"rawlog": `2017/04/05 21:57:46 some_file.go:10: {"title":"request_finished"}`,
"title": "request_finished",
"decoder_msg_type": "Kayvee",
"prefix": "2017/04/05 21:57:46 some_file.go:10: ",
"postfix": "",
"env": "deploy-env",
"container_env": "env",
"container_app": "app",
"container_task": "abcd1234-1a3b-1a3b-1234-d76552f4b7ef",
},
ExpectedError: nil,
},
ParseAndEnhanceSpec{
Title: "Parses a Kayvee log line from an ECS app, with override to container_app",
Line: `2017-04-05T21:57:46.794862+00:00 ip-10-0-0-0 env--app/arn%3Aaws%3Aecs%3Aus-west-1%3A999988887777%3Atask%2Fabcd1234-1a3b-1a3b-1234-d76552f4b7ef[3291]: 2017/04/05 21:57:46 some_file.go:10: {"title":"request_finished","container_app":"force-app"}`,
ExpectedOutput: map[string]interface{}{
"timestamp": logTime3,
"hostname": "ip-10-0-0-0",
"programname": `env--app/arn%3Aaws%3Aecs%3Aus-west-1%3A999988887777%3Atask%2Fabcd1234-1a3b-1a3b-1234-d76552f4b7ef`,
"rawlog": `2017/04/05 21:57:46 some_file.go:10: {"title":"request_finished","container_app":"force-app"}`,
"title": "request_finished",
"decoder_msg_type": "Kayvee",
"prefix": "2017/04/05 21:57:46 some_file.go:10: ",
"postfix": "",
"env": "deploy-env",
"container_env": "env",
"container_app": "force-app",
"container_task": "abcd1234-1a3b-1a3b-1234-d76552f4b7ef",
},
ExpectedError: nil,
},
ParseAndEnhanceSpec{
Title: "Parses a non-Kayvee log line",
Line: `2017-04-05T21:57:46.794862+00:00 ip-10-0-0-0 env--app/arn%3Aaws%3Aecs%3Aus-west-1%3A999988887777%3Atask%2Fabcd1234-1a3b-1a3b-1234-d76552f4b7ef[3291]: some log`,
ExpectedOutput: map[string]interface{}{
"timestamp": logTime3,
"hostname": "ip-10-0-0-0",
"programname": `env--app/arn%3Aaws%3Aecs%3Aus-west-1%3A999988887777%3Atask%2Fabcd1234-1a3b-1a3b-1234-d76552f4b7ef`,
"rawlog": `some log`,
"env": "deploy-env",
"decoder_msg_type": "syslog",
"container_env": "env",
"container_app": "app",
"container_task": "abcd1234-1a3b-1a3b-1234-d76552f4b7ef",
},
ExpectedError: nil,
},
ParseAndEnhanceSpec{
Title: "Fails to parse non-RSyslog, non-Fluent log line",
Line: `not rsyslog`,
ExpectedOutput: map[string]interface{}{},
ExpectedError: fmt.Errorf(""),
},
ParseAndEnhanceSpec{
Title: "Parses JSON values",
Line: `2017-04-05T21:57:46.794862+00:00 ip-10-0-0-0 env--app/arn%3Aaws%3Aecs%3Aus-west-1%3A999988887777%3Atask%2Fabcd1234-1a3b-1a3b-1234-d76552f4b7ef[3291]: 2017/04/05 21:57:46 some_file.go:10: {"title":"request_finished", "nested": {"a":"b"}}`,
ExpectedOutput: map[string]interface{}{
"timestamp": logTime3,
"hostname": "ip-10-0-0-0",
"programname": `env--app/arn%3Aaws%3Aecs%3Aus-west-1%3A999988887777%3Atask%2Fabcd1234-1a3b-1a3b-1234-d76552f4b7ef`,
"rawlog": `2017/04/05 21:57:46 some_file.go:10: {"title":"request_finished", "nested": {"a":"b"}}`,
"title": "request_finished",
"decoder_msg_type": "Kayvee",
"prefix": "2017/04/05 21:57:46 some_file.go:10: ",
"postfix": "",
"env": "deploy-env",
"container_env": "env",
"container_app": "app",
"container_task": "abcd1234-1a3b-1a3b-1234-d76552f4b7ef",
"nested": map[string]interface{}{"a": "b"},
},
ExpectedError: nil,
},
ParseAndEnhanceSpec{
Title: "Log with timestamp time.RFC3339 format",
Line: `2017-04-05T21:57:46+00:00 mongo-docker-pipeline-r10-4 diamond[24099] Signal Received: 15`,
ExpectedOutput: map[string]interface{}{
"env": "deploy-env",
"hostname": "mongo-docker-pipeline-r10-4",
"programname": "diamond",
"decoder_msg_type": "syslog",
"rawlog": "Signal Received: 15",
"timestamp": logTime2,
},
},
ParseAndEnhanceSpec{
Title: "RDS Slowquery Log rdsadmin",
Line: `2017-04-05T21:57:46+00:00 aws-rds production-aurora-test-db: Slow query: # Time: 190921 16:02:59
# User@Host: rdsadmin[rdsadmin] @ localhost [] Id: 1
# Query_time: 22.741550 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0SET timestamp=1569081779;call action start_seamless_scaling('AQEAAB1P/PAIqvTHEQFJAEkojZUoH176FGJttZ62JF5QmRehaf0S0VFTa+5MPJdYQ9k0/sekBlnMi8U=', 300000, 2);
SET timestamp=1569862702;`,
ExpectedOutput: map[string]interface{}{
"env": "deploy-env",
"hostname": "aws-rds",
"programname": "production-aurora-test-db",
"decoder_msg_type": "syslog",
"rawlog": "Slow query: # Time: 190921 16:02:59\n# User@Host: rdsadmin[rdsadmin] @ localhost [] Id: 1\n# Query_time: 22.741550 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0SET timestamp=1569081779;call action start_seamless_scaling('AQEAAB1P/PAIqvTHEQFJAEkojZUoH176FGJttZ62JF5QmRehaf0S0VFTa+5MPJdYQ9k0/sekBlnMi8U=', 300000, 2);\nSET timestamp=1569862702;",
"timestamp": logTime2,
"user": "rdsadmin[rdsadmin]",
"user_id": "1",
},
},
ParseAndEnhanceSpec{
Title: "RDS Slowquery Log clever user",
Line: `2017-04-05T21:57:46+00:00 aws-rds production-aurora-test-db: Slow query: # Time: 190921 16:02:59
# User@Host: clever[clever] @ [10.1.11.112] Id: 868
# Query_time: 2.000270 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0
SET timestamp=1571090308;
select sleep(2);`,
ExpectedOutput: map[string]interface{}{
"env": "deploy-env",
"hostname": "aws-rds",
"programname": "production-aurora-test-db",
"decoder_msg_type": "syslog",
"rawlog": "Slow query: # Time: 190921 16:02:59\n# User@Host: clever[clever] @ [10.1.11.112] Id: 868\n# Query_time: 2.000270 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0\nSET timestamp=1571090308;\nselect sleep(2);",
"timestamp": logTime2,
"user": "clever[clever]",
"user_id": "868",
},
},
{
Title: "Valid fluent log",
Line: `{
"container_id": "b17752cdd47a480712eca6c9774d782f68b50a876446faec5e26c9e8846bd29e",
"container_name": "/ecs-env--app--d--2-2-env--app-e295a2dcf6f9ac849101",
"ecs_cluster": "arn:aws:ecs:us-east-1:589690932525:cluster/pod-2870425d-e4b1-4869-b2b7-a6d9fade9be1",
"ecs_task_arn": "arn:aws:ecs:us-east-1:589690932525:task/pod-2870425d-e4b1-4869-b2b7-a6d9fade9be1/7c1ccb5cb5c44582808b9e516b479eb6",
"ecs_task_definition": "env--app--d--2:2",
"fluent_ts": "2020-08-13T21:10:57.000+0000",
"log": "2020/08/13 21:10:57 {\"title\": \"request-finished\"}",
"source": "stderr"
}`,
ExpectedOutput: map[string]interface{}{
"timestamp": logTime4,
"rawlog": "2020/08/13 21:10:57 {\"title\": \"request-finished\"}",
"hostname": "aws-fargate",
"decoder_msg_type": "Kayvee",
"title": "request-finished",
"container_app": "app",
"container_env": "env",
"container_task": "7c1ccb5cb5c44582808b9e516b479eb6",
"prefix": "2020/08/13 21:10:57 ",
"postfix": "",
"env": "deploy-env",
},
ExpectedError: nil,
},
{
Title: "fluent log missing ecs_task_definition still parses and has container_task",
Line: `{
"container_id": "b17752cdd47a480712eca6c9774d782f68b50a876446faec5e26c9e8846bd29e",
"container_name": "/ecs-env--app--d--2-2-env--app-e295a2dcf6f9ac849101",
"ecs_cluster": "arn:aws:ecs:us-east-1:589690932525:cluster/pod-2870425d-e4b1-4869-b2b7-a6d9fade9be1",
"ecs_task_arn": "arn:aws:ecs:us-east-1:589690932525:task/pod-2870425d-e4b1-4869-b2b7-a6d9fade9be1/7c1ccb5cb5c44582808b9e516b479eb6",
"fluent_ts": "2020-08-13T21:10:57.000+0000",
"log": "2020/08/13 21:10:57 {\"title\": \"request-finished\"}",
"source": "stderr"
}`,
ExpectedOutput: map[string]interface{}{
"timestamp": logTime4,
"rawlog": "2020/08/13 21:10:57 {\"title\": \"request-finished\"}",
"hostname": "aws-fargate",
"decoder_msg_type": "Kayvee",
"title": "request-finished",
"container_task": "7c1ccb5cb5c44582808b9e516b479eb6",
"prefix": "2020/08/13 21:10:57 ",
"postfix": "",
"env": "deploy-env",
},
},
{
Title: "fluent log with bad ecs_task_definition format still parses and has container_task",
Line: `{
"container_id": "b17752cdd47a480712eca6c9774d782f68b50a876446faec5e26c9e8846bd29e",
"container_name": "/ecs-env--app--d--2-2-env--app-e295a2dcf6f9ac849101",
"ecs_cluster": "arn:aws:ecs:us-east-1:589690932525:cluster/pod-2870425d-e4b1-4869-b2b7-a6d9fade9be1",
"ecs_task_arn": "arn:aws:ecs:us-east-1:589690932525:task/pod-2870425d-e4b1-4869-b2b7-a6d9fade9be1/7c1ccb5cb5c44582808b9e516b479eb6",
"ecs_task_definition": "env--app",
"fluent_ts": "2020-08-13T21:10:57.000+0000",
"log": "2020/08/13 21:10:57 {\"title\": \"request-finished\"}",
"source": "stderr"
}`,
ExpectedOutput: map[string]interface{}{
"timestamp": logTime4,
"rawlog": "2020/08/13 21:10:57 {\"title\": \"request-finished\"}",
"hostname": "aws-fargate",
"decoder_msg_type": "Kayvee",
"title": "request-finished",
"container_task": "7c1ccb5cb5c44582808b9e516b479eb6",
"prefix": "2020/08/13 21:10:57 ",
"postfix": "",
"env": "deploy-env",
},
},
{
Title: "fluent log missing ecs_task_arn still parses and has containter_env and app",
Line: `{
"container_id": "b17752cdd47a480712eca6c9774d782f68b50a876446faec5e26c9e8846bd29e",
"container_name": "/ecs-env--app--d--2-2-env--app-e295a2dcf6f9ac849101",
"ecs_cluster": "arn:aws:ecs:us-east-1:589690932525:cluster/pod-2870425d-e4b1-4869-b2b7-a6d9fade9be1",
"ecs_task_definition": "env--app--d--2:2",
"fluent_ts": "2020-08-13T21:10:57.000+0000",
"log": "2020/08/13 21:10:57 {\"title\": \"request-finished\"}",
"source": "stderr"
}`,
ExpectedOutput: map[string]interface{}{
"timestamp": logTime4, // time.Date(2020, 8, 13, 21, 10, 57, 0, time.UTC),
"rawlog": "2020/08/13 21:10:57 {\"title\": \"request-finished\"}",
"hostname": "aws-fargate",
"decoder_msg_type": "Kayvee",
"title": "request-finished",
"container_env": "env",
"container_app": "app",
"prefix": "2020/08/13 21:10:57 ",
"postfix": "",
"env": "deploy-env",
},
},
{
Title: "fluent log missing timestamp is an error",
Line: `{
"container_id": "b17752cdd47a480712eca6c9774d782f68b50a876446faec5e26c9e8846bd29e",
"container_name": "/ecs-env--app--d--2-2-env--app-e295a2dcf6f9ac849101",
"ecs_cluster": "arn:aws:ecs:us-east-1:589690932525:cluster/pod-2870425d-e4b1-4869-b2b7-a6d9fade9be1",
"ecs_task_arn": "arn:aws:ecs:us-east-1:589690932525:task/pod-2870425d-e4b1-4869-b2b7-a6d9fade9be1/7c1ccb5cb5c44582808b9e516b479eb6",
"ecs_task_definition": "env--app--d--2:2",
"ts": "2020-08-13T21:10:57.000+0000",
"log": "2020/08/13 21:10:57 {\"deploy_env\":\"env\",\"level\":\"info\",\"pod-account\":\"589690932525\",\"pod-id\":\"2870425d-e4b1-4869-b2b7-a6d9fade9be1\",\"pod-region\":\"us-east-1\",\"pod-shortname\":\"us-east-1-dev-canary-2870425d\",\"source\":\"app-service\",\"title\":\"NumFDs\",\"type\":\"gauge\",\"value\":33,\"via\":\"process-metrics\"}",
"source": "stderr"
}`,
ExpectedOutput: nil,
ExpectedError: BadLogFormatError{},
},
{
Title: "fluent log with bad timestamp format is an error",
Line: `{
"container_id": "b17752cdd47a480712eca6c9774d782f68b50a876446faec5e26c9e8846bd29e",
"container_name": "/ecs-env--app--d--2-2-env--app-e295a2dcf6f9ac849101",
"ecs_cluster": "arn:aws:ecs:us-east-1:589690932525:cluster/pod-2870425d-e4b1-4869-b2b7-a6d9fade9be1",
"ecs_task_arn": "arn:aws:ecs:us-east-1:589690932525:task/pod-2870425d-e4b1-4869-b2b7-a6d9fade9be1/7c1ccb5cb5c44582808b9e516b479eb6",
"ecs_task_definition": "env--app--d--2:2",
"fluent_ts": "2020-08-13T21:10:57.000Z",
"log": "2020/08/13 21:10:57 {\"deploy_env\":\"env\",\"level\":\"info\",\"pod-account\":\"589690932525\",\"pod-id\":\"2870425d-e4b1-4869-b2b7-a6d9fade9be1\",\"pod-region\":\"us-east-1\",\"pod-shortname\":\"us-east-1-dev-canary-2870425d\",\"source\":\"app-service\",\"title\":\"NumFDs\",\"type\":\"gauge\",\"value\":33,\"via\":\"process-metrics\"}",
"source": "stderr"
}`,
ExpectedOutput: nil,
ExpectedError: BadLogFormatError{},
},
{
Title: "Valid fluent log with overrides for container_env, app, and task",
Line: `{
"container_id": "b17752cdd47a480712eca6c9774d782f68b50a876446faec5e26c9e8846bd29e",
"container_name": "/ecs-env--app--d--2-2-env--app-e295a2dcf6f9ac849101",
"ecs_cluster": "arn:aws:ecs:us-east-1:589690932525:cluster/pod-2870425d-e4b1-4869-b2b7-a6d9fade9be1",
"ecs_task_arn": "arn:aws:ecs:us-east-1:589690932525:task/pod-2870425d-e4b1-4869-b2b7-a6d9fade9be1/7c1ccb5cb5c44582808b9e516b479eb6",
"ecs_task_definition": "env--app--d--2:2",
"fluent_ts": "2020-08-13T21:10:57.000+0000",
"log": "2020/08/13 21:10:57 {\"title\": \"request-finished\", \"container_env\": \"env2\", \"container_task\": \"task\", \"container_app\": \"app2\"}",
"source": "stderr"
}`,
ExpectedOutput: map[string]interface{}{
"timestamp": logTime4,
"rawlog": "2020/08/13 21:10:57 {\"title\": \"request-finished\", \"container_env\": \"env2\", \"container_task\": \"task\", \"container_app\": \"app2\"}",
"hostname": "aws-fargate",
"decoder_msg_type": "Kayvee",
"title": "request-finished",
"container_app": "app2",
"container_env": "env2",
"container_task": "task",
"prefix": "2020/08/13 21:10:57 ",
"postfix": "",
"env": "deploy-env",
},
ExpectedError: nil,
},
}
for _, spec := range specs {
t.Run(fmt.Sprintf(spec.Title), func(t *testing.T) {
assert := assert.New(t)
fields, err := ParseAndEnhance(spec.Line, "deploy-env")
if spec.ExpectedError != nil {
assert.Error(err)
assert.True(errors.As(err, &spec.ExpectedError))
return
}
assert.NoError(err)
assert.Equal(spec.ExpectedOutput, fields)
})
}
}
func TestGetContainerMeta(t *testing.T) {
type containerMetaSpec struct {
description string
input map[string]interface{}
wantErr bool
wantContainerEnv string
wantContainerApp string
wantContainerTask string
}
tests := []containerMetaSpec{
{
description: "Must have a programname to get container meta",
input: map[string]interface{}{
"programname": "",
},
wantErr: true,
},
{
description: "Can parse a programname",
input: map[string]interface{}{
"programname": `env1--app2/arn%3Aaws%3Aecs%3Aus-west-1%3A589690932525%3Atask%2Fabcd1234-1a3b-1a3b-1234-d76552f4b7ef`,
},
wantContainerEnv: "env1",
wantContainerApp: "app2",
wantContainerTask: "abcd1234-1a3b-1a3b-1234-d76552f4b7ef",
},
{
description: "Can override just 'env'",
input: map[string]interface{}{
"programname": `env1--app2/arn%3Aaws%3Aecs%3Aus-west-1%3A589690932525%3Atask%2Fabcd1234-1a3b-1a3b-1234-d76552f4b7ef`,
"container_env": "force-env",
},
wantContainerEnv: "force-env",
wantContainerApp: "app2",
wantContainerTask: "abcd1234-1a3b-1a3b-1234-d76552f4b7ef",
},
{
description: "Can override just 'app'",
input: map[string]interface{}{
"programname": `env1--app2/arn%3Aaws%3Aecs%3Aus-west-1%3A589690932525%3Atask%2Fabcd1234-1a3b-1a3b-1234-d76552f4b7ef`,
"container_app": "force-app",
},
wantContainerEnv: "env1",
wantContainerApp: "force-app",
wantContainerTask: "abcd1234-1a3b-1a3b-1234-d76552f4b7ef",
},
{
description: "Can override just 'task'",
input: map[string]interface{}{
"programname": `env1--app2/arn%3Aaws%3Aecs%3Aus-west-1%3A589690932525%3Atask%2Fabcd1234-1a3b-1a3b-1234-d76552f4b7ef`,
"container_task": "force-task",
},
wantContainerEnv: "env1",
wantContainerApp: "app2",
wantContainerTask: "force-task",
},
{
description: "Can override all fields",
input: map[string]interface{}{
"programname": `env1--app2/arn%3Aaws%3Aecs%3Aus-west-1%3A589690932525%3Atask%2Fabcd1234-1a3b-1a3b-1234-d76552f4b7ef`,
"container_task": "force-task",
"container_app": "force-app",
"container_env": "force-env",
},
wantContainerEnv: "force-env",
wantContainerApp: "force-app",
wantContainerTask: "force-task",
},
}
for _, tcase := range tests {
assert := assert.New(t)
syslog := map[string]interface{}{}
for k, v := range tcase.input {
syslog[k] = v
}
newSyslog, err := addContainterMetaToSyslog(syslog)
if tcase.wantErr {
assert.Error(err)
continue
}
for k, v := range newSyslog {
switch k {
case "container_env":
assert.Equal(v, tcase.wantContainerEnv)
case "container_app":
assert.Equal(v, tcase.wantContainerApp)
case "container_task":
assert.Equal(v, tcase.wantContainerTask)
default:
assert.Equal(v, tcase.input[k])
}
}
}
}
func TestExtractKVMeta(t *testing.T) {
assert := assert.New(t)
tests := []struct {
Description string
Log map[string]interface{}
Team string
Language string
Version string
Names []string
ExpectedMetricsRoutes []MetricsRoute
ExpectedAnalyticsRoutes []AnalyticsRoute
ExpectedNotificationRoutes []NotificationRoute
ExpectedAlertRoutes []AlertRoute
}{
{
Description: "log line with no routes",
Names: []string{},
Log: map[string]interface{}{"hi": "hello!"},
},
{
Description: "empty _kvmeta",
Names: []string{},
Log: map[string]interface{}{
"hi": "hello!",
"_kvmeta": map[string]interface{}{},
},
},
{
Description: "_kvmeta with no routes",
Team: "green",
Version: "three",
Language: "tree",
Names: []string{},
Log: map[string]interface{}{
"hi": "hello!",
"_kvmeta": map[string]interface{}{
"team": "green",
"kv_version": "three",
"kv_language": "tree",
},
},
},
{
Description: "_kvmeta with metric routes",
Team: "green",
Version: "three",
Language: "tree",
Names: []string{"cool", "cool2"},
ExpectedMetricsRoutes: []MetricsRoute{
{
Series: "1,1,2,3,5,8,13",
Dimensions: []string{"app", "district"},
ValueField: "value",
RuleName: "cool",
},
{
Series: "1,1,2,6,24,120,720,5040",
Dimensions: []string{"app", "district"},
ValueField: "value",
RuleName: "cool2",
},
},
Log: map[string]interface{}{
"hi": "hello!",
"_kvmeta": map[string]interface{}{
"team": "green",
"kv_version": "three",
"kv_language": "tree",
"routes": []interface{}{
map[string]interface{}{
"type": "metrics",
"rule": "cool",
"series": "1,1,2,3,5,8,13",
"value_field": "value",
"dimensions": []interface{}{"app", "district"},
},
map[string]interface{}{
"type": "metrics",
"rule": "cool2",
"series": "1,1,2,6,24,120,720,5040",
"dimensions": []interface{}{"app", "district"},
},
},
},
},
},
{
Description: "_kvmeta with analytic routes",
Team: "green",
Version: "christmas",
Language: "tree",
Names: []string{"what's-this?", "there's-app-invites-everywhere"},
ExpectedAnalyticsRoutes: []AnalyticsRoute{
{
Series: "what-is-this",
RuleName: "what's-this?",
},
{
RuleName: "there's-app-invites-everywhere",
Series: "there's-bts-in-the-air",
},
},
Log: map[string]interface{}{
"hi": "hello!",
"_kvmeta": map[string]interface{}{
"team": "green",
"kv_version": "christmas",
"kv_language": "tree",
"routes": []interface{}{
map[string]interface{}{
"type": "analytics",
"rule": "what's-this?",
"series": "what-is-this",
},
map[string]interface{}{
"type": "analytics",
"rule": "there's-app-invites-everywhere",
"series": "there's-bts-in-the-air",
},
},
},
},
},
{
Description: "_kvmeta with notification routes",
Team: "slack",
Version: "evergreen",
Language: "markdown-ish",
Names: []string{"did-you-know", "what's-the-catch"},
ExpectedNotificationRoutes: []NotificationRoute{
{
RuleName: "did-you-know",
Channel: "originally-slack",
Message: "was a gaming company",
Icon: ":video_game:",
User: "og slack bronie",
},
{
RuleName: "what's-the-catch",
Channel: "slack-is-built-with-php",
Message: "just like farmville",
Icon: ":ghost:",
User: "logging-pipeline",
},
},
Log: map[string]interface{}{
"hi": "hello!",
"_kvmeta": map[string]interface{}{
"team": "slack",
"kv_version": "evergreen",
"kv_language": "markdown-ish",
"routes": []interface{}{
map[string]interface{}{
"type": "notifications",
"rule": "did-you-know",
"channel": "originally-slack",
"message": "was a gaming company",
"icon": ":video_game:",
"user": "og slack bronie",
},
map[string]interface{}{
"type": "notifications",
"rule": "what's-the-catch",
"channel": "slack-is-built-with-php",
"message": "just like farmville",
},
},
},
},
},
{
Description: "_kvmeta with alert routes",
Team: "a-team",
Version: "old",
Language: "jive",
Names: []string{"last-call", "watch-out-now"},
ExpectedAlertRoutes: []AlertRoute{
{
RuleName: "last-call",
Series: "doing-it-til-we-fall",
Dimensions: []string{"who", "where"},
StatType: "gauge",
ValueField: "status",
},
{
RuleName: "watch-out-now",
Series: "dem-gators-gonna-bite-ya",
Dimensions: []string{"how-fresh", "how-clean"},
StatType: "counter",
ValueField: "value",
},
},
Log: map[string]interface{}{
"hi": "hello!",
"_kvmeta": map[string]interface{}{
"team": "a-team",
"kv_version": "old",
"kv_language": "jive",
"routes": []interface{}{
map[string]interface{}{
"type": "alerts",
"rule": "last-call",
"series": "doing-it-til-we-fall",
"dimensions": []interface{}{"who", "where"},
"stat_type": "gauge",
"value_field": "status",
},
map[string]interface{}{
"type": "alerts",
"rule": "watch-out-now",
"series": "dem-gators-gonna-bite-ya",
"dimensions": []interface{}{"how-fresh", "how-clean"},
},
},
},
},
},
{
Description: "_kvmeta with all types of routes",
Team: "diversity",
Version: "kv-routes",
Language: "understanding",
Names: []string{
"all-combos", "there's-app-invites-everywhere", "what's-the-catch", "last-call",
},
ExpectedMetricsRoutes: []MetricsRoute{
{
RuleName: "all-combos",
Series: "1,1,2,6,24,120,720,5040",
Dimensions: []string{"fact", "orial"},
ValueField: "value",
},
},
ExpectedAnalyticsRoutes: []AnalyticsRoute{
{
RuleName: "there's-app-invites-everywhere",
Series: "there's-bts-in-the-air",
},
},
ExpectedNotificationRoutes: []NotificationRoute{
{
RuleName: "what's-the-catch",
Channel: "slack-is-built-with-php",
Message: "just like farmville",
Icon: ":ghost:",
User: "logging-pipeline",
},
},
ExpectedAlertRoutes: []AlertRoute{
{
RuleName: "last-call",
Series: "doing-it-til-we-fall",
Dimensions: []string{"who", "where"},
StatType: "gauge",
ValueField: "status",
},
},
Log: map[string]interface{}{
"hi": "hello!",
"_kvmeta": map[string]interface{}{
"team": "diversity",
"kv_version": "kv-routes",
"kv_language": "understanding",
"routes": []interface{}{
map[string]interface{}{
"type": "metrics",
"rule": "all-combos",
"series": "1,1,2,6,24,120,720,5040",
"dimensions": []interface{}{"fact", "orial"},
},
map[string]interface{}{
"type": "analytics",
"rule": "there's-app-invites-everywhere",
"series": "there's-bts-in-the-air",
},
map[string]interface{}{
"type": "notifications",
"rule": "what's-the-catch",
"channel": "slack-is-built-with-php",
"message": "just like farmville",
},
map[string]interface{}{
"type": "alerts",
"rule": "last-call",
"series": "doing-it-til-we-fall",
"dimensions": []interface{}{"who", "where"},
"stat_type": "gauge",
"value_field": "status",
},
},
},
},
},
}
for _, test := range tests {
t.Log(test.Description)
kvmeta := ExtractKVMeta(test.Log)
assert.Equal(test.Team, kvmeta.Team)
assert.Equal(test.Language, kvmeta.Language)
assert.Equal(test.Version, kvmeta.Version)
assert.EqualValues(
sort.StringSlice(test.Names), sort.StringSlice(kvmeta.Routes.RuleNames()),
)
assert.Equal(len(test.ExpectedMetricsRoutes), len(kvmeta.Routes.MetricsRoutes()))
for idx, route := range kvmeta.Routes.MetricsRoutes() {
expected := test.ExpectedMetricsRoutes[idx]
assert.Exactly(expected, route)
}
assert.Equal(len(test.ExpectedAnalyticsRoutes), len(kvmeta.Routes.AnalyticsRoutes()))
for idx, route := range kvmeta.Routes.AnalyticsRoutes() {
expected := test.ExpectedAnalyticsRoutes[idx]
assert.Exactly(expected, route)
}
assert.Equal(len(test.ExpectedNotificationRoutes), len(kvmeta.Routes.NotificationRoutes()))
for idx, route := range kvmeta.Routes.NotificationRoutes() {
expected := test.ExpectedNotificationRoutes[idx]
assert.Exactly(expected, route)
}
assert.Equal(len(test.ExpectedAlertRoutes), len(kvmeta.Routes.AlertRoutes()))
for idx, route := range kvmeta.Routes.AlertRoutes() {
expected := test.ExpectedAlertRoutes[idx]
assert.Exactly(expected, route)
}
}
}
// Benchmarks
const benchmarkLine = `2017-04-05T21:57:46.794862+00:00 ip-10-0-0-0 env--app/arn%3Aaws%3Aecs%3Aus-west-1%3A999988887777%3Atask%2Fabcd1234-1a3b-1a3b-1234-d76552f4b7ef[3291]: 2017/04/05 21:57:46 some_file.go:10: {"title":"request_finished"}`
func BenchmarkFieldsFromKayvee(b *testing.B) {
for n := 0; n < b.N; n++ {
_, err := FieldsFromKayvee(benchmarkLine)
if err != nil {
b.FailNow()
}
}
}
func BenchmarkFieldsFromSyslog(b *testing.B) {
for n := 0; n < b.N; n++ {
_, err := FieldsFromSyslog(benchmarkLine)
if err != nil {
b.FailNow()
}
}
}
func BenchmarkParseAndEnhance(b *testing.B) {
for n := 0; n < b.N; n++ {
_, err := ParseAndEnhance(benchmarkLine, "env")
if err != nil {
b.FailNow()
}
}
}
Reference in a new issue View git blame Copy permalink