Panic on acc.AddFields on added minmax aggregation

[toni-moreno]

Bug report

Panic when processing log parsed measurements with minmax aggregator

2016/12/13 11:12:15 I! Using config file: C:\Program Files\Telegraf\telegraf.conf
2016-12-13T10:12:15Z D! Attempting connection to output: file
2016-12-13T10:12:15Z D! Successfully connected to output: file
2016-12-13T10:12:15Z I! Starting Telegraf (version 1.0.0-beta3-249-g1128477)
2016-12-13T10:12:15Z I! Loaded outputs: file
2016-12-13T10:12:15Z I! Loaded inputs: inputs.logparser
2016-12-13T10:12:15Z I! Tags enabled: host=WIN-PIUVQOCD78A
2016-12-13T10:12:15Z I! Agent Config: Interval:10s, Quiet:false, Hostname:"WIN-PIUVQOCD78A", Flush Interval:10s
2016/12/13 11:12:15 Seeked C:/Aplicaciones/online/peticions.log - &{Offset:0 Whence:2}
2016/12/13 11:12:19 Re-opening truncated file C:/Aplicaciones/online/peticions.log ...
2016/12/13 11:12:19 Successfully reopened truncated C:/Aplicaciones/online/peticions.log
2016-12-13T10:12:29Z D! Output [file] buffer fullness: 0 / 1000 metrics.
panic: runtime error: invalid memory address or nil pointer dereference
[signal 0xc0000005 code=0x0 addr=0x90 pc=0x51d400]

goroutine 20 [running]:
panic(0xf02f80, 0xc042004090)
        C:/Go/src/runtime/panic.go:500 +0x1af
github.com/influxdata/telegraf/internal/models.(*RunningAggregator).MakeMetric(0xc04200fc20, 0xc04236d600, 0xd, 0xc0423b7f50, 0xc0423b7a70, 0x3, 0xecfe1c099, 0xe00000000, 0x1749f60, 0x1749f60, ...)
        C:/Users/Administrator/Desktop/workspace/src/github.com/influxdata/telegraf/internal/models/running_aggregator.go:73 +0x160
github.com/influxdata/telegraf/agent.(*accumulator).AddFields(0xc04229ece0, 0xc04236d600, 0xd, 0xc0423b7f50, 0xc0423b7a70, 0x0, 0x0, 0x0)
        C:/Users/Administrator/Desktop/workspace/src/github.com/influxdata/telegraf/agent/accumulator.go:52 +0xeb
github.com/influxdata/telegraf/plugins/aggregators/minmax.(*MinMax).Push(0xc04201e040, 0x167cfe0, 0xc04229ece0)
        C:/Users/Administrator/Desktop/workspace/src/github.com/influxdata/telegraf/plugins/aggregators/minmax/minmax.go:96 +0x37e
github.com/influxdata/telegraf/internal/models.(*RunningAggregator).push(0xc04200fc20, 0x167cfe0, 0xc04229ece0)
        C:/Users/Administrator/Desktop/workspace/src/github.com/influxdata/telegraf/internal/models/running_aggregator.go:104 +0x4e
github.com/influxdata/telegraf/internal/models.(*RunningAggregator).Run(0xc04200fc20, 0x167cfe0, 0xc04229ece0, 0xc04202c540)
        C:/Users/Administrator/Desktop/workspace/src/github.com/influxdata/telegraf/internal/models/running_aggregator.go:160 +0x5ce
github.com/influxdata/telegraf/agent.(*Agent).Run.func2(0xc0420055f0, 0xc04202c8a0, 0xc04201e050, 0xc04202c540, 0xc04200fc20)
        C:/Users/Administrator/Desktop/workspace/src/github.com/influxdata/telegraf/agent/agent.go:366 +0xe0
created by github.com/influxdata/telegraf/agent.(*Agent).Run
        C:/Users/Administrator/Desktop/workspace/src/github.com/influxdata/telegraf/agent/agent.go:367 +0x3be

Relevant telegraf.conf:

[[outputs.file]]

    files = ["C:/Program Files/Telegraf/metrics_output_TEST.txt","stdout"]
    data_format = "influx"

[[inputs.logparser]]

files = ["C:/Aplicaciones/online/peticions.log"]
 from_beginning = false
 [inputs.logparser.tags]
  instance = "01"

 [inputs.logparser.grok]
  patterns = ["%{LOG_FORMAT}"]
  measurement = "peticions"
  custom_patterns = '''
  LOG_FORMAT %{DATE:date:drop} %{TIME:time:drop}-%{LOGLEVEL:level:drop}-\[\]-Resultado: %{DATA:result:tag}, TOTAL: %{INT:time_taken} ms., RequestId: %{DATA:req_id:drop}, FileName: %{DATA:filename:drop}
    '''
[aggregators.minmax]]
  period = "10s"        
  drop_original = false  # drop the original metrics.
  namepass = ["peticions"]

System info:

Telegraf version: master (b58926d)
OS: Windows 2008 R2 64bits

Agent parsing log OK without the Aggregator, in this scenario these are the output parsed measurements.

peticions,result=KO,instance=01,host=WIN-PIUVQOCD78A time_taken="20001" 1481624377136036400
peticions_ocr,result=KO,instance=01,host=WIN-PIUVQOCD78A time_taken="20079" 1481624377136036401
peticions,instance=01,host=WIN-PIUVQOCD78A,result=KO time_taken="20032" 1481624377136036402
peticions,result=OK,instance=01,host=WIN-PIUVQOCD78A time_taken="3609" 1481624377136036403
peticions,result=OK,instance=01,host=WIN-PIUVQOCD78A time_taken="4812" 1481624377136928500
peticions,result=OK,instance=01,host=WIN-PIUVQOCD78A time_taken="4188" 1481624377136928501
peticions,result=KO,instance=01,host=WIN-PIUVQOCD78A time_taken="20032" 1481624377136928502
peticions,result=KO,instance=01,host=WIN-PIUVQOCD78A time_taken="20015" 1481624377136928503

Steps to reproduce:

1. Configure telegraf.conf as described before
   2.- create the log with this script

#!/bin/bash
> C:/Aplicaciones/online/peticions.log
while /bin/true
do
sleep 8

cat <<EOF  >> C:/Aplicaciones/cvc-online/peticions.log
16/11/2016 13:08:54-INFO-[]-Resultado: KO, TOTAL: 20001 ms., RequestId: fd359df5-b09f-48e1-ab62-52ffc3662656, FileName: asdffa.pdf
16/11/2016 14:04:11-INFO-[]-Resultado: KO, TOTAL: 20079 ms., RequestId: 0001, FileName: asdfaf.pdf
16/11/2016 15:40:47-INFO-[]-Resultado: KO, TOTAL: 20032 ms., RequestId: 1f4d43ac-8f91-4c2e-bb6e-ac7407843c02, FileName: assssss.pdf
16/11/2016 16:00:17-INFO-[]-Resultado: OK, TOTAL: 3609 ms., RequestId: e166afb8-a2e8-4360-b0c0-243d05201027, FileName: bbbbbbbbbbbb.pdf
16/11/2016 16:50:39-INFO-[]-Resultado: OK, TOTAL: 4812 ms., RequestId: , FileName: asssssssssssssssss.pdf
16/11/2016 17:47:19-INFO-[]-Resultado: OK, TOTAL: 4188 ms., RequestId: 96405fbb-6040-4416-b2fb-3e989001411d, FileName: bbbbbbbbbbbbbbbbb.pdf
16/11/2016 19:35:10-INFO-[]-Resultado: KO, TOTAL: 20032 ms., RequestId: 56027b74-7d5f-4478-a16c-4dbf01ce2ae3, FileName: aaaaaaaaaaaa.pdf
16/11/2016 19:36:38-INFO-[]-Resultado: KO, TOTAL: 20015 ms., RequestId: bc0da322-f94d-4776-ba3c-4426564b168f, FileName: xxxxxxxxxxxxx.pdf
EOF

done

3-Execute

C:"Program Files"\Telegraf\telegraf.exe --config C:"Program Files"\Telegraf\telegraf.conf --test

Expected behavior:

Output with time_taken_max , time_taken_min output

Actual behavior:

a PANIC

[sparrc]

I'll look into getting this fixed, but I can tell you off the bat that you won't get any aggregated measurements with this parsing pattern. You are parsing time_taken as a string, and it needs to be an int.

I believe you want to change %{INT:time_taken} to %{INT:time_taken:int} (this might also fix the panic)

[toni-moreno]

Lots of thanks @sparrc !! You are right with time_taken as int the aggregator works fine