Filebeat to Logstash - broken pipe

Elastic Stack Beats
1

Hi,
It seems the filebeat misses acks from logstash in my testing rig.

My arrangement
Both Filebeat and Logstash runs on sigle Mac Sierra (10.12.6)

Filebeat
v.5.5.0

Config

filebeat.prospectors:
     - input_type: log
       paths:
         - /Users/me/logstashin.txt
 
 output.logstash:
       hosts: ["127.0.0.1:5044"]

Logstash
v.5.5.0

Config

input {
  beats {
    port => 5044 
  }
}

output {
  stdout { }
}

Steps to repro

At the beginning I clear monitored file logstashin.txt

I delete file registry in the filebeat/data directory

I start logstash and wait until it runs

me@ProjeKCt ~/bin/logstash-5.5.0 $ bin/logstash -f beat.conf

I start filebeat:

me@ProjeKCt ~/bin/filebeat-5.5.0-darwin-x86_64 $ ./filebeat -e -c filebeat.yml -d "publish"

Then I put the following content to the logstashin.txt

pear
apple 
cherry

I got the following output from the filebeat:

2017/08/02 12:59:59.352053 log.go:91: INFO Harvester started for file: /Users/me/logstashin.txt
2017/08/02 13:00:04.352374 client.go:214: DBG  Publish: {
  "@timestamp": "2017-08-02T12:59:59.352Z",
  "beat": {
    "hostname": "ProjeKCt.local",
    "name": "ProjeKCt.local",
    "version": "5.5.0"
  },
  "input_type": "log",
  "message": "pear",
  "offset": 5,
  "source": "/Users/me/logstashin.txt",
  "type": "log"
}
2017/08/02 13:00:04.352499 client.go:214: DBG  Publish: {
  "@timestamp": "2017-08-02T12:59:59.352Z",
  "beat": {
    "hostname": "ProjeKCt.local",
    "name": "ProjeKCt.local",
    "version": "5.5.0"
  },
  "input_type": "log",
  "message": "apple ",
  "offset": 12,
  "source": "/Users/me/logstashin.txt",
  "type": "log"
}
2017/08/02 13:00:04.352567 client.go:214: DBG  Publish: {
  "@timestamp": "2017-08-02T12:59:59.352Z",
  "beat": {
    "hostname": "ProjeKCt.local",
    "name": "ProjeKCt.local",
    "version": "5.5.0"
  },
  "input_type": "log",
  "message": "cherry",
  "offset": 19,
  "source": "/Users/me/logstashin.txt",
  "type": "log"
}
2017/08/02 13:00:04.352602 output.go:109: DBG  output worker: publish 3 events
2017/08/02 13:00:04.499623 sync.go:70: DBG  Events sent: 4
2017/08/02 13:00:29.350998 metrics.go:39: INFO Non-zero metrics in the last 30s: filebeat.harvester.open_files=1 filebeat.harvester.running=1 filebeat.harvester.started=1 libbeat.logstash.call_count.PublishEvents=1 libbeat.logstash.publish.read_bytes=6 libbeat.logstash.publish.write_bytes=275 libbeat.logstash.published_and_acked_events=3 libbeat.publisher.published_events=3 publish.events=4 registrar.states.current=1 registrar.states.update=4 registrar.writes=2

And output from the logstash:

2017-08-02T11:55:22.080Z ProjeKCt.local pear
2017-08-02T11:55:22.080Z ProjeKCt.local apple
2017-08-02T11:55:22.080Z ProjeKCt.local cherry

Then I add the line apricot into logstashin.txt.

Filebeat outputs:

2017/08/02 13:01:29.357144 log.go:91: INFO Harvester started for file: /Users/me/logstashin.txt
2017/08/02 13:01:29.357729 client.go:214: DBG  Publish: {
  "@timestamp": "2017-08-02T13:01:29.357Z",
  "beat": {
    "hostname": "ProjeKCt.local",
    "name": "ProjeKCt.local",
    "version": "5.5.0"
  },
  "input_type": "log",
  "message": "pear",
  "offset": 5,
  "source": "/Users/me/logstashin.txt",
  "type": "log"
}
2017/08/02 13:01:29.357782 client.go:214: DBG  Publish: {
  "@timestamp": "2017-08-02T13:01:29.357Z",
  "beat": {
    "hostname": "ProjeKCt.local",
    "name": "ProjeKCt.local",
    "version": "5.5.0"
  },
  "input_type": "log",
  "message": "apple ",
  "offset": 12,
  "source": "/Users/me/logstashin.txt",
  "type": "log"
}
2017/08/02 13:01:29.357818 client.go:214: DBG  Publish: {
  "@timestamp": "2017-08-02T13:01:29.357Z",
  "beat": {
    "hostname": "ProjeKCt.local",
    "name": "ProjeKCt.local",
    "version": "5.5.0"
  },
  "input_type": "log",
  "message": "cherry",
  "offset": 19,
  "source": "/Users/me/logstashin.txt",
  "type": "log"
}
2017/08/02 13:01:29.357864 client.go:214: DBG  Publish: {
  "@timestamp": "2017-08-02T13:01:29.357Z",
  "beat": {
    "hostname": "ProjeKCt.local",
    "name": "ProjeKCt.local",
    "version": "5.5.0"
  },
  "input_type": "log",
  "message": "apricot",
  "offset": 27,
  "source": "/Users/me/logstashin.txt",
  "type": "log"
}
2017/08/02 13:01:29.357885 output.go:109: DBG  output worker: publish 4 events
2017/08/02 13:01:29.358257 sync.go:85: ERR Failed to publish events caused by: write tcp 127.0.0.1:55038->127.0.0.1:5044: write: broken pipe
2017/08/02 13:01:29.358278 single.go:91: INFO Error publishing events (retrying): write tcp 127.0.0.1:55038->127.0.0.1:5044: write: broken pipe
2017/08/02 13:01:30.370035 sync.go:70: DBG  Events sent: 5
2017/08/02 13:01:59.351005 metrics.go:39: INFO Non-zero metrics in the last 30s: filebeat.harvester.open_files=1 filebeat.harvester.running=1 filebeat.harvester.started=1 libbeat.logstash.call_count.PublishEvents=2 libbeat.logstash.publish.read_bytes=6 libbeat.logstash.publish.write_bytes=317 libbeat.logstash.publish.write_errors=1 libbeat.logstash.published_and_acked_events=4 libbeat.logstash.published_but_not_acked_events=4 libbeat.publisher.published_events=4 publish.events=5 registrar.states.current=1 registrar.states.update=5 registrar.writes=1

There is a broken pipe error in the output.

Logstash outputs

2017-08-02T13:01:29.357Z ProjeKCt.local pear
2017-08-02T13:01:29.357Z ProjeKCt.local apple
2017-08-02T13:01:29.357Z ProjeKCt.local cherry
2017-08-02T13:01:29.357Z ProjeKCt.local apricot

Filebeat repeated all the data sent previously and appended apricot.

2

Thanks for the detailed description. I will try if I can reproduce this.

  1. How long did you want until you did update the file. Logstash is closing 'inactive' connections (client_connectivity_timeout setting). Filebeat reconnects and sends events again. You have the exact log message (is pipe broken on write or read)? Also check the logstash output debug messages about number of events being send.
  2. did you update the file via echo "apricot" >> filename or via editor? Most editors create a complete new file with new inode on update. This forces filebeat to send the complete new file with old content.
3

Hi Steffen,

Thanks for you answer.

First of all, the problem disappeared after I restarted operating system. Before that I restarted only filebeat and logstash and I always got the behaviour I described in my request.

After I restarted computer I can do the same steps as before and system works correctly.

Regarding your questions:

  1. I updated file when I got response to the screen. I guess my reactions were not longer than 15 seconds. I behave the same way today and system works well.

  2. I updated the file using VIM during my both unsuccessful and successful attempts.

4

yeah, with vim the resends seem to happen quite often. As vim normally creates a new file on save (with new inode). for these kind of tests use echo "msg" >> file, as this command truly appends new lines to a file, without creating a new file.

5

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.