From 27f2434e3ec9f1533466ca316beba8b9915c17de Mon Sep 17 00:00:00 2001 From: Hugo Oshiro Date: Mon, 31 Jul 2023 12:26:46 +0200 Subject: [PATCH 1/2] Preserve log keys order --- log_entry.go | 28 ++++++++++++++++----- log_entry_test.go | 62 +++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 84 insertions(+), 6 deletions(-) create mode 100644 log_entry_test.go diff --git a/log_entry.go b/log_entry.go index ab963d56..15ac3b93 100644 --- a/log_entry.go +++ b/log_entry.go @@ -5,6 +5,7 @@ package plugin import ( "encoding/json" + "regexp" "time" ) @@ -64,13 +65,28 @@ func parseJSON(input []byte) (*logEntry, error) { delete(raw, "@timestamp") } - // Parse dynamic KV args from the hclog payload. - for k, v := range raw { - entry.KVPairs = append(entry.KVPairs, &logEntryKV{ - Key: k, - Value: v, - }) + orderedKeys := getOrderedKeys(input) + + // Parse dynamic KV args from the hclog payload in order + for _, k := range orderedKeys { + if v, ok := raw[k]; ok { + entry.KVPairs = append(entry.KVPairs, &logEntryKV{ + Key: k, + Value: v, + }) + } } return entry, nil } + +func getOrderedKeys(input []byte) []string { + r := regexp.MustCompile(`"([^"]+)":\s*`) + matches := r.FindAllStringSubmatch(string(input), -1) + + keys := make([]string, len(matches)) + for i, match := range matches { + keys[i] = match[1] + } + return keys +} diff --git a/log_entry_test.go b/log_entry_test.go new file mode 100644 index 00000000..a16342b0 --- /dev/null +++ b/log_entry_test.go @@ -0,0 +1,62 @@ +// Copyright (c) HashiCorp, Inc. +// SPDX-License-Identifier: MPL-2.0 + +package plugin + +import ( + "fmt" + "reflect" + "testing" +) + +func TestParseJson(t *testing.T) { + keys := []string{"firstKey", "secondKey", "thirdKey"} + + input := []byte( + fmt.Sprintf( + `{"@level":"info","@message":"msg","@timestamp":"2023-07-28T17:50:47.333365+02:00","%s":"1","%s":"2","%s":"3"}`, + keys[0], + keys[1], + keys[2], + ), + ) + + // the behavior is non deterministic, that's why this test is repeated multiple times + for i := 0; i < 100; i++ { + entry, err := parseJSON(input) + if err != nil { + t.Fatalf("err: %s", err) + } + + for i := 0; i < len(keys); i++ { + if keys[i] != entry.KVPairs[i].Key { + t.Fatalf("expected: %v\ngot: %v", keys[i], entry.KVPairs[i].Key) + } + } + } + +} + +func TestGetOrderedKeys(t *testing.T) { + hclogKeys := []string{"@level", "@message", "@timestamp"} + customKeys := []string{"firstKey", "secondKey", "thirdKey"} + + input := []byte( + fmt.Sprintf( + `{"%s":"info","%s":"msg","%s":"2023-07-28T17:50:47.333365+02:00","%s":"1","%s":"2","%s":"3"}`, + hclogKeys[0], + hclogKeys[1], + hclogKeys[2], + customKeys[0], + customKeys[1], + customKeys[2], + ), + ) + + expectedKeys := append(hclogKeys, customKeys...) + actualKeys := getOrderedKeys(input) + + if !reflect.DeepEqual(expectedKeys, actualKeys) { + t.Fatalf("expected: %v\ngot: %v", expectedKeys, actualKeys) + } +} From eb7fad461dcb10297e13c4e145812755deccd6f5 Mon Sep 17 00:00:00 2001 From: Hugo Oshiro Date: Tue, 1 Aug 2023 11:42:39 +0200 Subject: [PATCH 2/2] Change key ordering method --- log_entry.go | 43 ++++++++++++++++++++++++++++--------------- log_entry_test.go | 43 +++++++++++++------------------------------ 2 files changed, 41 insertions(+), 45 deletions(-) diff --git a/log_entry.go b/log_entry.go index 15ac3b93..05e10243 100644 --- a/log_entry.go +++ b/log_entry.go @@ -4,8 +4,9 @@ package plugin import ( + "bytes" "encoding/json" - "regexp" + "sort" "time" ) @@ -23,6 +24,12 @@ type logEntryKV struct { Value interface{} `json:"value"` } +// jsonKey has the log key and its position in the raw log. It's used for ordering +type jsonKey struct { + key string + position int +} + // flattenKVPairs is used to flatten KVPair slice into []interface{} // for hclog consumption. func flattenKVPairs(kvs []*logEntryKV) []interface{} { @@ -65,28 +72,34 @@ func parseJSON(input []byte) (*logEntry, error) { delete(raw, "@timestamp") } - orderedKeys := getOrderedKeys(input) + orderedKeys := getOrderedKeys(input, raw) // Parse dynamic KV args from the hclog payload in order for _, k := range orderedKeys { - if v, ok := raw[k]; ok { - entry.KVPairs = append(entry.KVPairs, &logEntryKV{ - Key: k, - Value: v, - }) - } + entry.KVPairs = append(entry.KVPairs, &logEntryKV{ + Key: k.key, + Value: raw[k.key], + }) } return entry, nil } -func getOrderedKeys(input []byte) []string { - r := regexp.MustCompile(`"([^"]+)":\s*`) - matches := r.FindAllStringSubmatch(string(input), -1) +// getOrderedKeys returns the log keys ordered according to their original order of appearance +func getOrderedKeys(input []byte, raw map[string]interface{}) []jsonKey { + var orderedKeys []jsonKey - keys := make([]string, len(matches)) - for i, match := range matches { - keys[i] = match[1] + for key := range raw { + position := bytes.Index(input, []byte("\""+key+"\":")) + orderedKeys = append(orderedKeys, jsonKey{ + key, + position, + }) } - return keys + + sort.Slice(orderedKeys, func(i, j int) bool { + return orderedKeys[i].position < orderedKeys[j].position + }) + + return orderedKeys } diff --git a/log_entry_test.go b/log_entry_test.go index a16342b0..a5fc6f29 100644 --- a/log_entry_test.go +++ b/log_entry_test.go @@ -5,19 +5,23 @@ package plugin import ( "fmt" - "reflect" "testing" ) func TestParseJson(t *testing.T) { keys := []string{"firstKey", "secondKey", "thirdKey"} + raw := map[string]interface{}{ + keys[0]: "thirdKey", // we use keys as values to test correct key matching + keys[1]: "secondKey", + keys[2]: "firstKey", + } input := []byte( fmt.Sprintf( - `{"@level":"info","@message":"msg","@timestamp":"2023-07-28T17:50:47.333365+02:00","%s":"1","%s":"2","%s":"3"}`, - keys[0], - keys[1], - keys[2], + `{"@level":"info","@message":"msg","@timestamp":"2023-07-28T17:50:47.333365+02:00","%s":"%s","%s":"%s","%s":"%s"}`, + keys[0], raw[keys[0]], + keys[1], raw[keys[1]], + keys[2], raw[keys[2]], ), ) @@ -30,33 +34,12 @@ func TestParseJson(t *testing.T) { for i := 0; i < len(keys); i++ { if keys[i] != entry.KVPairs[i].Key { - t.Fatalf("expected: %v\ngot: %v", keys[i], entry.KVPairs[i].Key) + t.Fatalf("expected key: %v\ngot key: %v", keys[i], entry.KVPairs[i].Key) + } + if raw[keys[i]] != entry.KVPairs[i].Value { + t.Fatalf("expected value: %v\ngot value: %v", keys[i], entry.KVPairs[i].Key) } } } } - -func TestGetOrderedKeys(t *testing.T) { - hclogKeys := []string{"@level", "@message", "@timestamp"} - customKeys := []string{"firstKey", "secondKey", "thirdKey"} - - input := []byte( - fmt.Sprintf( - `{"%s":"info","%s":"msg","%s":"2023-07-28T17:50:47.333365+02:00","%s":"1","%s":"2","%s":"3"}`, - hclogKeys[0], - hclogKeys[1], - hclogKeys[2], - customKeys[0], - customKeys[1], - customKeys[2], - ), - ) - - expectedKeys := append(hclogKeys, customKeys...) - actualKeys := getOrderedKeys(input) - - if !reflect.DeepEqual(expectedKeys, actualKeys) { - t.Fatalf("expected: %v\ngot: %v", expectedKeys, actualKeys) - } -}