Input execd does not handle newline characters in strings

[gregschrock]

I'm having trouble with the new execd plugin where it's producing errors when my string fields contain newline characters.

Relevant telegraf.conf:

[agent]
debug = true
interval = "5s"
flush_interval = "5s"
round_interval = true

[[outputs.file]]
  files = ["stdout"]

[[inputs.execd]]

  command = ["/usr/bin/tail", "-F", "/tmp/multiline.txt"]

  signal = "none"
  data_format = "influx"

System info:

# telegraf --version
Telegraf 1.14.2 (git: HEAD fb74eaf2)

# cat /etc/centos-release
CentOS Linux release 7.5.1804 (Core)

Steps to reproduce:

1. Create a file whose lines contain a string with newline characters

$ echo 'event message="my
message" 1587128639239000000' > /tmp/multiline.txt

2. Configure the execd plugin to tail that file

$ echo '
[agent]
debug = true
interval = "5s"
flush_interval = "5s"
round_interval = true

[[outputs.file]]
  files = ["stdout"]

[[inputs.execd]]

  command = ["/usr/bin/tail", "-F", "/tmp/multiline.txt"]

  signal = "none"
  data_format = "influx"
' > /tmp/execd_multiline.conf

3. Run telegraf with the config and observe the error

$ telegraf --config /tmp/execd_multiline.conf
2020-05-05T15:37:50Z I! Starting Telegraf 1.14.2
2020-05-05T15:37:50Z I! Loaded inputs: execd
2020-05-05T15:37:50Z I! Loaded aggregators:
2020-05-05T15:37:50Z I! Loaded processors:
2020-05-05T15:37:50Z I! Loaded outputs: file
2020-05-05T15:37:50Z I! Tags enabled: host=t174-dut1.openstacklocal
2020-05-05T15:37:50Z I! [agent] Config: Interval:5s, Quiet:false, Hostname:"t174-dut1.openstacklocal", Flush Interval:5s
2020-05-05T15:37:50Z D! [agent] Initializing plugins
2020-05-05T15:37:50Z D! [agent] Connecting outputs
2020-05-05T15:37:50Z D! [agent] Attempting connection to [outputs.file]
2020-05-05T15:37:50Z D! [agent] Successfully connected to outputs.file
2020-05-05T15:37:50Z D! [agent] Starting service inputs
2020-05-05T15:37:50Z D! [inputs.execd] Starting process: [/usr/bin/tail -F /tmp/multiline-message.txt]
2020-05-05T15:37:50Z E! [inputs.execd] Error in plugin: E! [inputs.execd] Parse error: metric parse error: expected field at 1:18: "event message=\"my"
2020-05-05T15:37:50Z E! [inputs.execd] Error in plugin: E! [inputs.execd] Parse error: metric parse error: expected field at 1:29: "message\" 1587128639239000000"
2020-05-05T15:38:00Z D! [outputs.file] Buffer fullness: 0 / 10000 metrics

Expected behavior:

I expect it to behave in the same way exec, which correctly parses the Influx line and produces it. If the input is updated to use exec:

$ echo '
[agent]
debug = true
interval = "5s"
flush_interval = "5s"
round_interval = true

[[outputs.file]]
  files = ["stdout"]

[[inputs.exec]]

  commands = ["/usr/bin/cat /tmp/multiline.txt",]
  data_format = "influx"
' > /tmp/exec_multiline.conf

and I run with that, things work fine. Specifically, this demonstrates the validity of the line content.

$ telegraf --config /tmp/exec_multiline.conf
2020-05-05T15:43:00Z I! Starting Telegraf 1.14.2
2020-05-05T15:43:00Z I! Loaded inputs: exec
2020-05-05T15:43:00Z I! Loaded aggregators:
2020-05-05T15:43:00Z I! Loaded processors:
2020-05-05T15:43:00Z I! Loaded outputs: file
2020-05-05T15:43:00Z I! Tags enabled: host=t174-dut1.openstacklocal
2020-05-05T15:43:00Z I! [agent] Config: Interval:5s, Quiet:false, Hostname:"t174-dut1.openstacklocal", Flush Interval:5s
2020-05-05T15:43:00Z D! [agent] Initializing plugins
2020-05-05T15:43:00Z D! [agent] Connecting outputs
2020-05-05T15:43:00Z D! [agent] Attempting connection to [outputs.file]
2020-05-05T15:43:00Z D! [agent] Successfully connected to outputs.file
2020-05-05T15:43:00Z D! [agent] Starting service inputs
event,host=t174-dut1.openstacklocal message="my
message" 1587128639000000000
2020-05-05T15:43:10Z D! [outputs.file] Wrote batch of 1 metrics in 571.894µs
2020-05-05T15:43:10Z D! [outputs.file] Buffer fullness: 0 / 10000 metrics

Additional Information

For my own sanity, I wrote a test demonstrating the issue. This is based off code that was just delivered here.

func TestParsesLinesContainingNewline(t *testing.T) {
	parser, err := parsers.NewInfluxParser()
	require.NoError(t, err)

	metrics := make(chan telegraf.Metric, 10)
	defer close(metrics)
	acc := agent.NewAccumulator(&TestMetricMaker{}, metrics)

	e := &Execd{
		Command:      []string{shell(), fileShellScriptPath()},
		RestartDelay: config.Duration(5 * time.Second),
		parser:       parser,
		Signal:       "STDIN",
		acc:          acc,
	}

	cases := []struct {
		Name  string
		Value string
	}{
		{
			Name:  "no-newline",
			Value: "my message",
		}, {
			Name:  "newline",
			Value: "my\nmessage",
		},
	}

	for _, test := range cases {
		t.Run(test.Name, func(t *testing.T) {
			line := fmt.Sprintf("event message=\"%v\" 1587128639239000000", test.Value)

			e.cmdReadOut(strings.NewReader(line))

			m := readChanWithTimeout(t, metrics, 1*time.Second)

			require.Equal(t, "event", m.Name())
			val, ok := m.GetField("message")
			require.True(t, ok)
			require.Equal(t, test.Value, val)
		})
	}
}

[ssoroka]

Thanks for this excellent issue, @gregschrock ; great detail!
it looks like we're not escaping the message properly. I'll take a look at it.

[ssoroka]

All fixed. Thanks again for the bug report and the test. That made it easy to track down.

[gregschrock]

Thank you for the quick turn around! It is appreciated!