Correctly parse rfc3339 timezone and Nanosecond (elastic#8346)

* Correctly parse rfc3339 timezone and Nanosecond The code was not correctly creating the time and was isntead making events appear to be a few years in the future. The nanosecond extraction was not on the right scale for the time.Date, the commit fixes the behavior and do assertions with the go parser.
jsoriano · Sep 24, 2018 · 6204fce · 6204fce
1 parent 35068ee
commit 6204fce
Show file tree

Hide file tree

Showing 4 changed files with 105 additions and 34 deletions.
diff --git a/CHANGELOG.asciidoc b/CHANGELOG.asciidoc
@@ -62,6 +62,7 @@ https://github.com/elastic/beats/compare/v6.4.0...master[Check the HEAD diff]
 - Fixed a docker input error due to the offset update bug in partial log join.{pull}8177[8177]
 - Update CRI format to support partial/full tags. {pull}8265[8265]
 - Fix some errors happening when stopping syslog input. {pull}8347[8347]
+- Fix RFC3339 timezone and nanoseconds parsing with the syslog input. {pull}8346[8346]
 
 *Heartbeat*
 

diff --git a/filebeat/input/syslog/event.go b/filebeat/input/syslog/event.go
@@ -102,18 +102,20 @@ func (s *event) SetTimeZone(b []byte) {
 	}
 
 	// +00 +00:00 or +0000
+	// Use second value directly and don't use unecessary time.Duration.
+	// Time.FixedZone accepts number of seconds.
 	var h, m int
 	switch len(b[1:]) {
 	case 2:
-		h = int(time.Hour * time.Duration(bytesToInt(skipLeadZero(b[1:]))))
+		h = 3600 * bytesToInt(skipLeadZero(b[1:]))
 		s.loc = time.FixedZone("", d*h)
 	case 4:
-		h = int(time.Hour * time.Duration(bytesToInt(skipLeadZero(b[1:3]))))
-		m = int(time.Minute * time.Duration(bytesToInt(skipLeadZero(b[3:5]))))
+		h = 3600 * bytesToInt(skipLeadZero(b[1:3]))
+		m = 60 * bytesToInt(skipLeadZero(b[3:5]))
 		s.loc = time.FixedZone("", d*(h+m))
 	case 5:
-		h = int(time.Hour * time.Duration(bytesToInt(skipLeadZero(b[1:3]))))
-		m = int(time.Minute * time.Duration(bytesToInt(skipLeadZero(b[4:6]))))
+		h = 3600 * bytesToInt(skipLeadZero(b[1:3]))
+		m = 60 * bytesToInt(skipLeadZero(b[4:6]))
 		s.loc = time.FixedZone("", d*(h+m))
 	}
 }
@@ -271,8 +273,8 @@ func (s *event) HasPid() bool {
 func (s *event) SetNanosecond(b []byte) {
 	// We assume that we receive a byte array representing a nanosecond, this might not be
 	// always the case, so we have to pad it.
-	if len(b) < 7 {
-		s.nanosecond = bytesToInt(skipLeadZero(b)) * int(math.Pow10((7 - len(b))))
+	if len(b) < 9 {
+		s.nanosecond = bytesToInt(skipLeadZero(b)) * int(math.Pow10((9 - len(b))))
 	} else {
 		s.nanosecond = bytesToInt(skipLeadZero(b))
 	}

diff --git a/filebeat/input/syslog/event_test.go b/filebeat/input/syslog/event_test.go
@@ -63,16 +63,84 @@ func TestHasPid(t *testing.T) {
 }
 
 func TestDateParsing(t *testing.T) {
-	now := time.Now()
+	// 2018-09-12T18:14:04.537585-07:00
 	e := newEvent()
-	e.SetDay(itb(now.Day()))
-	e.SetMonth([]byte(now.Month().String()))
-	e.SetHour(itb(now.Hour()))
-	e.SetMinute(itb(now.Minute()))
-	e.SetSecond(itb(now.Second()))
-	e.SetNanosecond(itb(now.Nanosecond()))
-	new := e.Timestamp(time.Local)
-	assert.Equal(t, now.UTC(), new)
+	e.SetYear([]byte("2018"))
+	e.SetDay(itb(12))
+	e.SetMonth([]byte("Sept"))
+	e.SetHour(itb(18))
+	e.SetMinute(itb(14))
+	e.SetSecond(itb(04))
+	e.SetNanosecond(itb(5555))
+
+	// Use google parser to compare.
+	t1, _ := time.Parse(time.RFC3339, "2018-09-12T18:14:04.5555-07:00")
+	t1 = t1.UTC()
+	t2, _ := time.Parse(time.RFC3339, "2018-09-12T18:14:04.5555+07:00")
+	t2 = t2.UTC()
+	alreadyutc := time.Date(2018, 9, 12, 18, 14, 04, 555500000, time.UTC)
+
+	tests := []struct {
+		name     string
+		tzBytes  []byte
+		expected time.Time
+	}{
+		{name: "-07:00", tzBytes: []byte("-07:00"), expected: t1},
+		{name: "-0700", tzBytes: []byte("-0700"), expected: t1},
+		{name: "-07", tzBytes: []byte("-07"), expected: t1},
+		{name: "+07:00", tzBytes: []byte("+07:00"), expected: t2},
+		{name: "+0700", tzBytes: []byte("+0700"), expected: t2},
+		{name: "+07", tzBytes: []byte("+07"), expected: t2},
+		{name: "z+00:00", tzBytes: []byte("z+00:00"), expected: alreadyutc},
+		{name: "z+0000", tzBytes: []byte("z+0000"), expected: alreadyutc},
+		{name: "z+00", tzBytes: []byte("z+00"), expected: alreadyutc},
+		{name: "Z+00:00", tzBytes: []byte("Z+00:00"), expected: alreadyutc},
+		{name: "Z+0000", tzBytes: []byte("Z+0000"), expected: alreadyutc},
+		{name: "Z+00", tzBytes: []byte("Z+00"), expected: alreadyutc},
+	}
+
+	for _, test := range tests {
+		t.Run(test.name, func(t *testing.T) {
+			e.SetTimeZone(test.tzBytes)
+			new := e.Timestamp(nil)
+			assert.Equal(t, test.expected, new)
+		})
+	}
+}
+
+func TestNanosecondParsing(t *testing.T) {
+	e := newEvent()
+	e.SetYear([]byte("2018"))
+	e.SetDay(itb(12))
+	e.SetMonth([]byte("Sept"))
+	e.SetHour(itb(18))
+	e.SetMinute(itb(14))
+	e.SetSecond(itb(04))
+
+	// Use google parser to compare.
+	dt := func(s string) int {
+		ti, _ := time.Parse(time.RFC3339, s)
+		return ti.UTC().Nanosecond()
+	}
+
+	tests := []struct {
+		name       string
+		nanosecond []byte
+		expected   int
+	}{
+		{nanosecond: []byte("5555"), expected: dt("2018-09-12T18:14:04.5555-07:00")},
+		{nanosecond: []byte("5"), expected: dt("2018-09-12T18:14:04.5-07:00")},
+		{nanosecond: []byte("0005"), expected: dt("2018-09-12T18:14:04.0005-07:00")},
+		{nanosecond: []byte("000545"), expected: dt("2018-09-12T18:14:04.000545-07:00")},
+		{nanosecond: []byte("00012345"), expected: dt("2018-09-12T18:14:04.00012345-07:00")},
+	}
+
+	for _, test := range tests {
+		t.Run(string(test.nanosecond), func(t *testing.T) {
+			e.SetNanosecond(test.nanosecond)
+			assert.Equal(t, test.expected, e.Nanosecond())
+		})
+	}
 }
 
 func TestIsValid(t *testing.T) {

diff --git a/filebeat/input/syslog/parser_test.go b/filebeat/input/syslog/parser_test.go
@@ -63,7 +63,7 @@ func TestParseSyslog(t *testing.T) {
 				hour:       2,
 				minute:     13,
 				second:     38,
-				nanosecond: 4000,
+				nanosecond: 400000,
 			},
 		},
 		{
@@ -81,8 +81,8 @@ func TestParseSyslog(t *testing.T) {
 				hour:       2,
 				minute:     13,
 				second:     38,
-				nanosecond: 6353220,
-				loc:        time.FixedZone("", int(-7*time.Hour)),
+				nanosecond: 635322000,
+				loc:        time.FixedZone("", -7*3600),
 			},
 		},
 		{
@@ -100,8 +100,8 @@ func TestParseSyslog(t *testing.T) {
 				hour:       2,
 				minute:     13,
 				second:     38,
-				nanosecond: 6353220,
-				loc:        time.FixedZone("", int(-7*time.Hour)),
+				nanosecond: 635322000,
+				loc:        time.FixedZone("", -7*3600),
 			},
 		},
 		{
@@ -119,8 +119,8 @@ func TestParseSyslog(t *testing.T) {
 				hour:       2,
 				minute:     13,
 				second:     38,
-				nanosecond: 6353220,
-				loc:        time.FixedZone("", int(-7*time.Hour)+int(-30*time.Minute)),
+				nanosecond: 635322000,
+				loc:        time.FixedZone("", -7*3600+-30*60),
 			},
 		},
 		{
@@ -138,8 +138,8 @@ func TestParseSyslog(t *testing.T) {
 				hour:       2,
 				minute:     13,
 				second:     38,
-				nanosecond: 6353220,
-				loc:        time.FixedZone("", int(-7*time.Hour)+int(-10*time.Minute)),
+				nanosecond: 635322000,
+				loc:        time.FixedZone("", -7*3600+-10*60),
 			},
 		},
 		{
@@ -157,8 +157,8 @@ func TestParseSyslog(t *testing.T) {
 				hour:       2,
 				minute:     13,
 				second:     38,
-				nanosecond: 6353220,
-				loc:        time.FixedZone("", int(-7*time.Hour)),
+				nanosecond: 635322000,
+				loc:        time.FixedZone("", -7*3600),
 			},
 		},
 		{
@@ -176,7 +176,7 @@ func TestParseSyslog(t *testing.T) {
 				hour:       2,
 				minute:     13,
 				second:     38,
-				nanosecond: 6353220,
+				nanosecond: 635322000,
 				loc:        time.UTC,
 			},
 		},
@@ -195,7 +195,7 @@ func TestParseSyslog(t *testing.T) {
 				hour:       2,
 				minute:     13,
 				second:     38,
-				nanosecond: 6353220,
+				nanosecond: 635322000,
 				loc:        time.UTC,
 			},
 		},
@@ -214,7 +214,7 @@ func TestParseSyslog(t *testing.T) {
 				hour:       2,
 				minute:     13,
 				second:     38,
-				nanosecond: 6353220,
+				nanosecond: 635322000,
 				loc:        time.UTC,
 			},
 		},
@@ -233,7 +233,7 @@ func TestParseSyslog(t *testing.T) {
 				hour:       2,
 				minute:     13,
 				second:     38,
-				nanosecond: 6353220,
+				nanosecond: 635322000,
 				loc:        time.UTC,
 			},
 		},
@@ -304,7 +304,7 @@ func TestParseSyslog(t *testing.T) {
 				minute:     31,
 				second:     24,
 				year:       2016,
-				nanosecond: 4000,
+				nanosecond: 400000,
 			},
 		},
 		{
@@ -341,7 +341,7 @@ func TestParseSyslog(t *testing.T) {
 		},
 		{
 			title: "time with nanosecond",
-			log:   []byte("Oct 11 22:14:15.0000005 --- last message repeated 1 time ---"),
+			log:   []byte("Oct 11 22:14:15.000000005 --- last message repeated 1 time ---"),
 			syslog: event{
 				priority:   -1,
 				message:    "--- last message repeated 1 time ---",
@@ -400,7 +400,7 @@ func TestParseSyslog(t *testing.T) {
 				hour:       22,
 				minute:     14,
 				second:     15,
-				nanosecond: 5764300,
+				nanosecond: 576430000,
 			},
 		},
 		{