Skip to content

Commit

Permalink
Cherry-pick elastic#8346 to 6.4: Correctly parse rfc3339 timezone and…
Browse files Browse the repository at this point in the history 
… Nanosecond (elastic#8432)

Cherry-pick of PR elastic#8346 to 6.4 branch. Original message: 

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.

bug was reported by @vjsamuel
  • Loading branch information
@ph
ph authored Sep 25, 2018
1 parent 4b87bb8 commit cff0152
Show file tree
Hide file tree
Showing 4 changed files with 105 additions and 34 deletions.
1 change: 1 addition & 0 deletions CHANGELOG.asciidoc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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*

Expand Down
16 changes: 9 additions & 7 deletions filebeat/input/syslog/event.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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))
}
}
Expand Down Expand Up @@ -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))
}
Expand Down
86 changes: 77 additions & 9 deletions filebeat/input/syslog/event_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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) {
Expand Down
36 changes: 18 additions & 18 deletions filebeat/input/syslog/parser_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -63,7 +63,7 @@ func TestParseSyslog(t *testing.T) {
hour: 2,
minute: 13,
second: 38,
nanosecond: 4000,
nanosecond: 400000,
},
},
{
Expand All @@ -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),
},
},
{
Expand All @@ -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),
},
},
{
Expand All @@ -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),
},
},
{
Expand All @@ -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),
},
},
{
Expand All @@ -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),
},
},
{
Expand All @@ -176,7 +176,7 @@ func TestParseSyslog(t *testing.T) {
hour: 2,
minute: 13,
second: 38,
nanosecond: 6353220,
nanosecond: 635322000,
loc: time.UTC,
},
},
Expand All @@ -195,7 +195,7 @@ func TestParseSyslog(t *testing.T) {
hour: 2,
minute: 13,
second: 38,
nanosecond: 6353220,
nanosecond: 635322000,
loc: time.UTC,
},
},
Expand All @@ -214,7 +214,7 @@ func TestParseSyslog(t *testing.T) {
hour: 2,
minute: 13,
second: 38,
nanosecond: 6353220,
nanosecond: 635322000,
loc: time.UTC,
},
},
Expand All @@ -233,7 +233,7 @@ func TestParseSyslog(t *testing.T) {
hour: 2,
minute: 13,
second: 38,
nanosecond: 6353220,
nanosecond: 635322000,
loc: time.UTC,
},
},
Expand Down Expand Up @@ -304,7 +304,7 @@ func TestParseSyslog(t *testing.T) {
minute: 31,
second: 24,
year: 2016,
nanosecond: 4000,
nanosecond: 400000,
},
},
{
Expand Down Expand Up @@ -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 ---",
Expand Down Expand Up @@ -400,7 +400,7 @@ func TestParseSyslog(t *testing.T) {
hour: 22,
minute: 14,
second: 15,
nanosecond: 5764300,
nanosecond: 576430000,
},
},
{
Expand Down

0 comments on commit cff0152

Please sign in to comment.