Exec plugin generating duplicate measurements

[rafaelabdo-zz]

I guess that I'm facing the same problem with "inputs_exec" as described here: #773

Some tips for this issue:

• I'm using influx format.
• The same content is generating different insertions, e.g. a file with 50 lines sometimes can insert 55, 56 or 52 lines into influxdb.
• I've tried to insert it manually into influxdb through curl but I haven't had the same issue.
• The content had nanoseconds at the end of each line.

[rafaelabdo-zz]

I'm currently using the version 1.0.0-beta1 but It happened on the previous version as well.

[sparrc]

Can you be more specific? What is the exec plugin executing? What metrics is the script generating?your config file? provide the script? output of the script that is being executed?

[rafaelabdo-zz]

It is executing an script made by us. Anyway and in order to avoid any doubt, I tried to send the output to a text file and I changed the configs to just read this file, the results were the same though. See configs below:

[[inputs.exec]]
  #command = "/path/of/script.sh"
  command = "cat /tmp/content.txt"
  data_format = "influx"
  interval = "1h"
  timeout = "60s"

The content was a variation, 50 lines to be precise, of:

antixxxx,tool=mysql-query,database=antixxxx,hostname=xxx.202.xxx.36,server=xxxx,scope=xxxx,product_key=xxxx,status=xxxx,product_name=xxxx,payment_method=xxxx orders=4 1449230399000000000

Just to add more information, the product name normally has spaces but I'm escaping all of them, like so:

product_name=PRODUCT\ NAME

[sparrc]

@rafaelabdo can you provide actual metrics that reproduce the issue? Unforunately there's not much I can do without reproducing it.

[rafaelabdo-zz]

Ok, see it below:

Config:

[[inputs.exec]]
  command = "cat /tmp/example.txt"
  data_format = "influx"
  interval = "1h"
  timeout = "60s"

Content:

antixxxx,tool=mysql-query,desc=DELTA0001,status=allow,info=cc orders=4 1449230399000000000
antixxxx,tool=mysql-query,desc=MIKE0003,status=allow,info=cc orders=1 1449230399000000000
antixxxx,tool=mysql-query,desc=MIKE0012,status=allow,info=cc orders=1 1449230399000000000
antixxxx,tool=mysql-query,desc=OSCARSM01,status=allow,info=cc orders=6 1449230399000000000
antixxxx,tool=mysql-query,desc=OSCARSM03,status=allow,info=cc orders=1 1449230399000000000
antixxxx,tool=mysql-query,desc=TANGO0002,status=allow,info=cc orders=4 1449230399000000000
antixxxx,tool=mysql-query,desc=TANGO0003,status=allow,info=cc orders=1 1449230399000000000
antixxxx,tool=mysql-query,desc=VICTORCPN1,status=allow,info=cc orders=1 1449230399000000000
antixxxx,tool=mysql-query,desc=ALAGA0001,status=allow,info=cc orders=1 1449230399000000000
antixxxx,tool=mysql-query,desc=DELTA0001,status=unallow,info=cc orders=2 1449230399000000000
antixxxx,tool=mysql-query,desc=OSCARSM02,status=unallow,info=cc orders=1 1449230399000000000
antixxxx,tool=mysql-query,desc=TANGO0002,status=unallow,info=cc orders=1 1449230399000000000
antixxxx,tool=mysql-query,desc=MIKE0012,status=allow,info=cc orders=1 1461733199000000000
antixxxx,tool=mysql-query,desc=OSCARSM01,status=allow,info=cc orders=6 1461733199000000000
antixxxx,tool=mysql-query,desc=OSCARSM02,status=allow,info=cc orders=1 1461733199000000000
antixxxx,tool=mysql-query,desc=TANGO0002,status=allow,info=cc orders=4 1461733199000000000
antixxxx,tool=mysql-query,desc=TANGO0003,status=allow,info=cc orders=1 1461733199000000000
antixxxx,tool=mysql-query,desc=DELTA0001,status=unallow,info=cc orders=1 1461733199000000000
antixxxx,tool=mysql-query,desc=UNIFORM0001,status=unallow,info=cc orders=1 1461733199000000000
antixxxx,tool=mysql-query,desc=XRAYG827,status=unallow,info=cc orders=1 1461733199000000000
antixxxx,tool=mysql-query,desc=ECHO0001,status=allow,info=cc orders=1 1462078799000000000
antixxxx,tool=mysql-query,desc=OSCARSM01,status=allow,info=cc orders=2 1462078799000000000
antixxxx,tool=mysql-query,desc=OSCARSM02,status=allow,info=cc orders=1 1462078799000000000
antixxxx,tool=mysql-query,desc=TANGO0002,status=allow,info=cc orders=1 1462078799000000000
antixxxx,tool=mysql-query,desc=TANGO0003,status=allow,info=cc orders=4 1462078799000000000
antixxxx,tool=mysql-query,desc=MIKE0003,status=allow,info=cc orders=1 1462085999000000000
antixxxx,tool=mysql-query,desc=OSCARSM01,status=allow,info=cc orders=1 1462085999000000000
antixxxx,tool=mysql-query,desc=TANGO0002,status=allow,info=cc orders=1 1462085999000000000
antixxxx,tool=mysql-query,desc=VICTORCPN1,status=allow,info=cc orders=1 1462085999000000000
antixxxx,tool=mysql-query,desc=DELTA0001,status=allow,info=cc orders=1 1463551199000000000
antixxxx,tool=mysql-query,desc=OSCARSM01,status=allow,info=cc orders=4 1463551199000000000
antixxxx,tool=mysql-query,desc=OSCARSM02,status=allow,info=cc orders=1 1463551199000000000
antixxxx,tool=mysql-query,desc=TANGO0002,status=allow,info=cc orders=4 1463551199000000000
antixxxx,tool=mysql-query,desc=TANGO0003,status=allow,info=cc orders=3 1463551199000000000
antixxxx,tool=mysql-query,desc=DELTA0001,status=unallow,info=cc orders=1 1463551199000000000
antixxxx,tool=mysql-query,desc=ECHO0001,status=allow,info=cc orders=2 1463554799000000000
antixxxx,tool=mysql-query,desc=LIMAROOT,status=allow,info=cc orders=1 1463554799000000000
antixxxx,tool=mysql-query,desc=OSCARSM01,status=allow,info=cc orders=8 1463554799000000000
antixxxx,tool=mysql-query,desc=OSCARSM02,status=allow,info=cc orders=1 1463554799000000000
antixxxx,tool=mysql-query,desc=TANGO0002,status=allow,info=cc orders=8 1463554799000000000
antixxxx,tool=mysql-query,desc=TANGO0003,status=allow,info=cc orders=2 1463554799000000000
antixxxx,tool=mysql-query,desc=UNIFORM0001,status=allow,info=cc orders=1 1463554799000000000
antixxxx,tool=mysql-query,desc=DELTA0001,status=unallow,info=cc orders=1 1463554799000000000
antixxxx,tool=mysql-query,desc=OSCARSM01,status=allow,info=cc orders=4 1463885999000000000
antixxxx,tool=mysql-query,desc=OSCARSM02,status=allow,info=cc orders=1 1463885999000000000
antixxxx,tool=mysql-query,desc=OSCARSM03,status=allow,info=cc orders=1 1463885999000000000
antixxxx,tool=mysql-query,desc=SIERRAL010,status=allow,info=cc orders=1 1463885999000000000
antixxxx,tool=mysql-query,desc=TANGO0002,status=allow,info=cc orders=6 1463885999000000000
antixxxx,tool=mysql-query,desc=TANGO0003,status=allow,info=cc orders=3 1463885999000000000
antixxxx,tool=mysql-query,desc=ECHO0001,status=allow,info=cc orders=1 1463903999000000000

Tests:

• 1st cleanup:

drop measurement antixxxx
drop series from antixxxx

• 1st Telegraf restart:

2016/06/16 13:11:06 Starting Telegraf (version 1.0.0-beta1)
2016/06/16 13:11:06 Loaded outputs: influxdb
2016/06/16 13:11:06 Loaded inputs: diskio mem swap system net cpu disk exec
2016/06/16 13:11:06 Tags enabled: host=xxxx team=xxxx tool=telegraf
2016/06/16 13:11:06 Agent Config: Interval:1m0s, Debug:false, Quiet:false, Hostname:"xxxx", Flush Interval:10s 
2016/06/16 13:12:12 Output [influxdb] buffer fullness: 72 / 10000 metrics. Total gathered metrics: 72. Total dropped metrics: 0.
2016/06/16 13:12:12 Output [influxdb] wrote batch of 72 metrics in 21.306601ms

• 1st result:

> select count(orders) from antixxxx
name: antixxxx
--------------
time    count
0   57

• 2nd cleanup:

drop measurement antixxxx
drop series from antixxxx

• 2nd Telegraf restart:

2016/06/16 13:13:46 Starting Telegraf (version 1.0.0-beta1)
2016/06/16 13:13:46 Loaded outputs: influxdb
2016/06/16 13:13:46 Loaded inputs: system net cpu disk diskio mem swap exec
2016/06/16 13:13:46 Tags enabled: host=xxxx team=xxxx tool=telegraf
2016/06/16 13:13:46 Agent Config: Interval:1m0s, Debug:false, Quiet:false, Hostname:"xxxx", Flush Interval:10s 
2016/06/16 13:14:15 Output [influxdb] buffer fullness: 72 / 10000 metrics. Total gathered metrics: 72. Total dropped metrics: 0.
2016/06/16 13:14:15 Output [influxdb] wrote batch of 72 metrics in 64.932341ms

• 2nd result:

select count(orders) from antixxxx
name: antixxxx
--------------
time    count
0   59

• 3rd cleanup:

drop measurement antixxxx
drop series from antixxxx

• 3rd Telegraf restart:

2016/06/16 13:15:08 Starting Telegraf (version 1.0.0-beta1)
2016/06/16 13:15:08 Loaded outputs: influxdb
2016/06/16 13:15:08 Loaded inputs: cpu disk diskio mem swap system net exec
2016/06/16 13:15:08 Tags enabled: host=xxxx team=xxxx tool=telegraf
2016/06/16 13:15:08 Agent Config: Interval:1m0s, Debug:false, Quiet:false, Hostname:"xxxx", Flush Interval:10s 
2016/06/16 13:16:17 Output [influxdb] buffer fullness: 72 / 10000 metrics. Total gathered metrics: 72. Total dropped metrics: 0.
2016/06/16 13:16:17 Output [influxdb] wrote batch of 72 metrics in 33.917919ms

• 3rd result:

select count(orders) from antixxxx
name: antixxxx
--------------
time    count
0   57

[sparrc]

can you provide your influxdb output config?

[rafaelabdo-zz]

Yes:

[[outputs.influxdb]]
  # The full HTTP or UDP endpoint URL for your InfluxDB instance.
  # Multiple urls can be specified but it is assumed that they are part of the same
  # cluster, this means that only ONE of the urls will be written to each interval.
  # urls = ["udp://localhost:8089"] # UDP endpoint example
  urls = ["https://xxxx.xxxx.com"] # required
  # The target database for metrics (telegraf will create it if not exists)
  database = "xxxx" # required
  # Precision of writes, valid values are n, u, ms, s, m, and h
  # note: using second precision greatly helps InfluxDB compression
  precision = "s"

  # Connection timeout (for the connection with InfluxDB), formatted as a string.
  # If not provided, will default to 0 (no timeout)
  timeout = "5s"
  username = "xxxx"
  password = "xxxx"

  # Set the user agent for HTTP POSTs (can be useful for log differentiation)
  user_agent = "telegraf"
  # Set UDP payload size, defaults to InfluxDB UDP Client default (512 bytes)
  # udp_payload = 512

[rafaelabdo-zz]

Is there anything else that could be helpful to reproduce this issue?

[sparrc]

I haven't had the chance to try to reproduce yet, please be patient, or submit a PR ;-)

[sparrc]

for my own debugging purposes, I got 50 points, 50 points, then 52 points:

> select * from antixxxx
name: antixxxx
--------------
time            desc        host    info    orders  status  tool
1449230399000000000 ALAGA0001   tyrion  cc  1   allow   mysql-query
1449230399000000000 VICTORCPN1  tyrion  cc  1   allow   mysql-query
1449230399000000000 TANGO0003   tyrion  cc  1   allow   mysql-query
1449230399000000000 TANGO0002   tyrion  cc  1   unallow mysql-query
1449230399000000000 TANGO0002   tyrion  cc  4   allow   mysql-query
1449230399000000000 OSCARSM03   tyrion  cc  1   allow   mysql-query
1449230399000000000 OSCARSM02   tyrion  cc  1   unallow mysql-query
1449230399000000000 OSCARSM01   tyrion  cc  6   allow   mysql-query
1449230399000000000 MIKE0012    tyrion  cc  1   allow   mysql-query
1449230399000000000 MIKE0003    tyrion  cc  1   allow   mysql-query
1449230399000000000 DELTA0001   tyrion  cc  2   unallow mysql-query
1449230399000000000 DELTA0001   tyrion  cc  4   allow   mysql-query
1461733199000000000 DELTA0001   tyrion  cc  1   unallow mysql-query
1461733199000000000 TANGO0002   tyrion  cc  4   allow   mysql-query
1461733199000000000 OSCARSM02   tyrion  cc  1   allow   mysql-query
1461733199000000000 OSCARSM01   tyrion  cc  6   allow   mysql-query
1461733199000000000 XRAYG827    tyrion  cc  1   unallow mysql-query
1461733199000000000 MIKE0012    tyrion  cc  1   allow   mysql-query
1461733199000000000 UNIFORM0001 tyrion  cc  1   unallow mysql-query
1461733199000000000 TANGO0003   tyrion  cc  1   allow   mysql-query
1462078799000000000 ECHO0001    tyrion  cc  1   allow   mysql-query
1462078799000000000 TANGO0003   tyrion  cc  4   allow   mysql-query
1462078799000000000 OSCARSM01   tyrion  cc  2   allow   mysql-query
1462078799000000000 TANGO0002   tyrion  cc  1   allow   mysql-query
1462078799000000000 OSCARSM02   tyrion  cc  1   allow   mysql-query
1462085999000000000 TANGO0002   tyrion  cc  1   allow   mysql-query
1462085999000000000 VICTORCPN1  tyrion  cc  1   allow   mysql-query
1462085999000000000 MIKE0003    tyrion  cc  1   allow   mysql-query
1462085999000000000 OSCARSM01   tyrion  cc  1   allow   mysql-query
1463551199000000000 DELTA0001   tyrion  cc  1   allow   mysql-query
1463551199000000000 OSCARSM02   tyrion  cc  1   allow   mysql-query
1463551199000000000 TANGO0003   tyrion  cc  3   allow   mysql-query
1463551199000000000 DELTA0001   tyrion  cc  1   unallow mysql-query
1463551199000000000 OSCARSM01   tyrion  cc  4   allow   mysql-query
1463551199000000000 TANGO0002   tyrion  cc  4   allow   mysql-query
1463554799000000000 OSCARSM01   tyrion  cc  8   allow   mysql-query
1463554799000000000 TANGO0002   tyrion  cc  8   allow   mysql-query
1463554799000000000 UNIFORM0001 tyrion  cc  1   allow   mysql-query
1463554799000000000 ECHO0001    tyrion  cc  2   allow   mysql-query
1463554799000000000 LIMAROOT    tyrion  cc  1   allow   mysql-query
1463554799000000000 DELTA0001   tyrion  cc  1   unallow mysql-query
1463554799000000000 OSCARSM02   tyrion  cc  1   allow   mysql-query
1463554799000000000 TANGO0003   tyrion  cc  2   allow   mysql-query
1463885999000000000 OSCARSM02   tyrion  cc  1   allow   mysql-query
1463885999000000000 TANGO0003   tyrion  cc  3   allow   mysql-query
1463885999000000000 OSCARSM01   tyrion  cc  4   allow   mysql-query
1463885999000000000 TANGO0002   tyrion  cc  6   allow   mysql-query
1463885999000000000 SIERRAL010  tyrion  cc  1   allow   mysql-query
1463885999000000000 OSCARSM03   tyrion  cc  1   allow   mysql-query
1463903999000000000 ECHO0001    tyrion  cc  1   allow   mysql-query

> select sum(orders) from antixxxx
name: antixxxx
--------------
time    sum
0   108

> select sum(orders) from antixxxx
name: antixxxx
--------------
time    sum
0   108

> select count(orders) from antixxxx
name: antixxxx
--------------
time    count
0   50

>
> drop measurement antixxxx
> select count(orders) from antixxxx
> select count(orders) from antixxxx
name: antixxxx
--------------
time    count
0   50

> select sum(orders) from antixxxx
name: antixxxx
--------------
time    sum
0   108

> drop measurement antixxxx
> select sum(orders) from antixxxx
name: antixxxx
--------------
time    sum
0   113

> select count(orders) from antixxxx
name: antixxxx
--------------
time    count
0   52

> select * from antixxxx
name: antixxxx
--------------
time            desc        host    info    orders  status  tool
1449230399000000000 ALAGA0001   tyrion  cc  1   allow   mysql-query
1449230399000000000 VICTORCPN1  tyrion  cc  1   allow   mysql-query
1449230399000000000 TANGO0003   tyrion  cc  1   allow   mysql-query
1449230399000000000 TANGO0002   tyrion  cc  1   unallow mysql-query
1449230399000000000 TANGO0002   tyrion  cc  4   allow   mysql-query
1449230399000000000 OSCARSM03   tyrion  cc  1   allow   mysql-query
1449230399000000000 OSCARSM02   tyrion  cc  1   unallow mysql-query
1449230399000000000 OSCARSM01   tyrion  cc  6   allow   mysql-query
1449230399000000000 MIKE0012    tyrion  cc  1   allow   mysql-query
1449230399000000000 MIKE0003    tyrion  cc  1   allow   mysql-query
1449230399000000000 DELTA0001   tyrion  cc  2   unallow mysql-query
1449230399000000000 DELTA0001   tyrion  cc  4   allow   mysql-query
1449230399000000000 DELTA0001   tyrion  cc  4   allow   mysql-query
1461733199000000000 DELTA0001   tyrion  cc  1   unallow mysql-query
1461733199000000000 TANGO0002   tyrion  cc  4   allow   mysql-query
1461733199000000000 OSCARSM02   tyrion  cc  1   allow   mysql-query
1461733199000000000 OSCARSM01   tyrion  cc  6   allow   mysql-query
1461733199000000000 XRAYG827    tyrion  cc  1   unallow mysql-query
1461733199000000000 MIKE0012    tyrion  cc  1   allow   mysql-query
1461733199000000000 UNIFORM0001 tyrion  cc  1   unallow mysql-query
1461733199000000000 TANGO0003   tyrion  cc  1   allow   mysql-query
1462078799000000000 ECHO0001    tyrion  cc  1   allow   mysql-query
1462078799000000000 TANGO0003   tyrion  cc  4   allow   mysql-query
1462078799000000000 OSCARSM01   tyrion  cc  2   allow   mysql-query
1462078799000000000 TANGO0002   tyrion  cc  1   allow   mysql-query
1462078799000000000 OSCARSM02   tyrion  cc  1   allow   mysql-query
1462085999000000000 TANGO0002   tyrion  cc  1   allow   mysql-query
1462085999000000000 VICTORCPN1  tyrion  cc  1   allow   mysql-query
1462085999000000000 MIKE0003    tyrion  cc  1   allow   mysql-query
1462085999000000000 OSCARSM01   tyrion  cc  1   allow   mysql-query
1463551199000000000 DELTA0001   tyrion  cc  1   allow   mysql-query
1463551199000000000 DELTA0001   tyrion  cc  1   unallow mysql-query
1463551199000000000 OSCARSM02   tyrion  cc  1   allow   mysql-query
1463551199000000000 OSCARSM01   tyrion  cc  4   allow   mysql-query
1463551199000000000 DELTA0001   tyrion  cc  1   allow   mysql-query
1463551199000000000 TANGO0003   tyrion  cc  3   allow   mysql-query
1463551199000000000 TANGO0002   tyrion  cc  4   allow   mysql-query
1463554799000000000 TANGO0003   tyrion  cc  2   allow   mysql-query
1463554799000000000 TANGO0002   tyrion  cc  8   allow   mysql-query
1463554799000000000 DELTA0001   tyrion  cc  1   unallow mysql-query
1463554799000000000 UNIFORM0001 tyrion  cc  1   allow   mysql-query
1463554799000000000 LIMAROOT    tyrion  cc  1   allow   mysql-query
1463554799000000000 OSCARSM02   tyrion  cc  1   allow   mysql-query
1463554799000000000 OSCARSM01   tyrion  cc  8   allow   mysql-query
1463554799000000000 ECHO0001    tyrion  cc  2   allow   mysql-query
1463885999000000000 OSCARSM01   tyrion  cc  4   allow   mysql-query
1463885999000000000 SIERRAL010  tyrion  cc  1   allow   mysql-query
1463885999000000000 TANGO0002   tyrion  cc  6   allow   mysql-query
1463885999000000000 OSCARSM03   tyrion  cc  1   allow   mysql-query
1463885999000000000 TANGO0003   tyrion  cc  3   allow   mysql-query
1463885999000000000 OSCARSM02   tyrion  cc  1   allow   mysql-query
1463903999000000000 ECHO0001    tyrion  cc  1   allow   mysql-query

[sparrc]

as far as I can tell this is not a telegraf issue, I wrote up a script for writing this data to InfluxDB using curl and I'm getting non-deterministic results as well....still trying to figure out what the issue with this data is:

curl -XPOST 'http://localhost:8086/write?db=telegraf' --data-binary '@/tmp/example.txt'

curl -G --silent 'http://localhost:8086/query' --data-urlencode "q=SELECT count(orders) FROM antixxxx" --data-urlencode "db=telegraf" # | jq '.results[0].series[0].values[0][1]'

curl -XPOST --silent 'http://localhost:8086/query' --data-urlencode "q=DROP MEASUREMENT antixxxx" --data-urlencode "db=telegraf" > /dev/null

(delete the comment on the 2nd line if you have jq installed, this will select only the count)

[sparrc]

AFAICT this is an influxdb bug, possibly related to dropping measurements, see influxdata/influxdb#7039

[sparrc]

@rafaelabdo you hit a very interesting corner case with the metrics you were writing, which was a bug in InfluxDB. This PR: influxdata/influxdb#7027 fixed it, and it was merged just after version 1.0.0-beta3 was released.

So the fix will be for the DB, and it will be ready in version 1.0 (or beta4, whichever comes first).