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. (cherry picked from commit 6204fce)
ph · Sep 25, 2018 · 41b8bc6 · 41b8bc6
1 parent 357d046
commit 41b8bc6
Show file tree

Hide file tree

Showing 4 changed files with 105 additions and 34 deletions.
diff --git a/CHANGELOG.asciidoc b/CHANGELOG.asciidoc
@@ -34,6 +34,7 @@ https://github.com/elastic/beats/compare/v6.4.1...6.4[Check the HEAD diff]
 *Filebeat*
 
 - 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,
 			},
 		},
 		{