elastic / elastic/beats

Filebeat stops harvesting logs

Open
#13,607 31 comments 4 reactions 0 assignees View on GitHub
bug Team:Integrations Team:Platforms
Dominant language
Go
Stars
12.7k
Forks
5k
Avg merge
2d 15m
Merged PRs (30d)
385

Description

1. Filebeat harvested logs correctly
2. Restarted logstash
3. New logs appear in Kibana
4. After some time, logs are not being harvested from a docker container, although new log entries are written to file

Note that logstash correctly receives logs from other containers harvested by filebeat.
Filebeat harvester didn't recover even after a few hours.

Filebeat configuration:
```
output.logstash:
hosts: ["logstash:5044"]
setup.kibana.host: http://kibana:5601
filebeat.autodiscover:
providers:
- type: docker
hints.enabled: true
```

Docker compose service:
```
web:
image: app:latest
expose:
- 80
labels:
co.elastic.logs/multiline.pattern: '^[[:space:]]+(at|\\.{3})\\b|^Caused by:'
co.elastic.logs/multiline.negate: false
co.elastic.logs/multiline.match: after
app: web
environment:
ELASTIC_APM_SERVER_URLS: http://apm:8200
```

My docker container that is not being harvested has id: **3252b7646a23293b6728941769f0412e2bd4b74b801ee09ab747c7cdfa74550c**

This container was also restarted at **2019-09-11 15:19:03,983**.
Last log entry correctly processed has timestamp **2019-09-11 15:19:37,235**.
Next log entry with timestamp **2019-09-11 15:20:15,276** and next ones are missing.

Filebeat relevant log:
```
2019-09-11T15:19:57.988Z INFO [monitoring] log/log.go:145 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":28150,"time":{"ms":120}},"total":{"ticks":54510,"time":{"ms":150},"value":54510},"user":{"ticks":26360,"time":{"ms":30}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":13},"info":{"ephemeral_id":"17c964bc-009e-4840-89b6-4b9c511cdf14","uptime":{"ms":15900511}},"memstats":{"gc_next":8939216,"memory_alloc":4663776,"memory_total":6966547888},"runtime":{"goroutines":93}},"filebeat":{"events":{"active":-2,"added":114,"done":116},"harvester":{"open_files":5,"running":5}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":116,"batches":13,"total":116},"read":{"bytes":78},"write":{"bytes":31559}},"pipeline":{"clients":8,"events":{"active":0,"published":114,"total":114},"queue":{"acked":116}}},"registrar":{"states":{"current":10,"update":116},"writes":{"success":13,"total":13}},"system":{"load":{"1":1.19,"15":0.58,"5":0.86,"norm":{"1":0.2975,"15":0.145,"5":0.215}}}}}}
2019-09-11T15:20:04.554Z INFO input/input.go:149 input ticker stopped
2019-09-11T15:20:04.554Z INFO input/input.go:167 Stopping Input: 9894227653855818847
2019-09-11T15:20:04.554Z INFO log/harvester.go:274 Reader was closed: /var/lib/docker/containers/3252b7646a23293b6728941769f0412e2bd4b74b801ee09ab747c7cdfa74550c/3252b7646a23293b6728941769f0412e2bd4b74b801ee09ab747c7cdfa74550c-json.log. Closing.
2019-09-11T15:20:27.995Z INFO [monitoring] log/log.go:145 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":28160,"time":{"ms":10}},"total":{"ticks":54610,"time":{"ms":100},"value":54610},"user":{"ticks":26450,"time":{"ms":90}}},"handles":{"limit":{"hard":1048576,"soft":1048576},"open":12},"info":{"ephemeral_id":"17c964bc-009e-4840-89b6-4b9c511cdf14","uptime":{"ms":15930517}},"memstats":{"gc_next":5878912,"memory_alloc":7557664,"memory_total":6986384152,"rss":-2998272},"runtime":{"goroutines":82}},"filebeat":{"events":{"added":31,"done":31},"harvester":{"closed":1,"open_files":4,"running":4}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":30,"batches":12,"total":30},"read":{"bytes":72},"write":{"bytes":17806}},"pipeline":{"clients":7,"events":{"active":0,"filtered":1,"published":30,"total":31},"queue":{"acked":30}}},"registrar":{"states":{"current":10,"update":31},"writes":{"success":13,"total":13}},"system":{"load":{"1":1.24,"15":0.6,"5":0.89,"norm":{"1":0.31,"15":0.15,"5":0.2225}}}}}}
```

Logstash restarted timeline log:
```
[2019-09-11T15:16:36,298][INFO ][logstash.runner ] Starting Logstash {"logstash.version"=>"7.3.0"}
..................
[2019-09-11T15:16:45,397][INFO ][logstash.agent ] Successfully started Logstash API endpoint {:port=>9600}
```

Filebeat repository entry:
```
{
"source": "/var/lib/docker/containers/3252b7646a23293b6728941769f0412e2bd4b74b801ee09ab747c7cdfa74550c/3252b7646a23293b6728941769f0412e2bd4b74b801ee09ab747c7cdfa74550c-json.log",
"offset": 794342,
"timestamp": "2019-09-11T15:20:04.5542604Z",
"ttl": -1,
"type": "container",
"meta": null,
"FileStateOS": {
"inode": 802588,
"device": 2049
}
}
```

Log file stats:
```
sh-4.2# stat 3252b7646a23293b6728941769f0412e2bd4b74b801ee09ab747c7cdfa74550c-json.log
File: '3252b7646a23293b6728941769f0412e2bd4b74b801ee09ab747c7cdfa74550c-json.log'
Size: 911932 Blocks: 1784 IO Block: 4096 regular file
Device: 801h/2049d Inode: 802588 Links: 1
Access: (0640/-rw-r-----) Uid: ( 0/ root) Gid: ( 0/ root)
Access: 2019-09-11 17:39:48.711393000 +0000
Modify: 2019-09-11 17:19:37.112086700 +0000
Change: 2019-09-11 17:19:37.112086700 +0000
Birth: -
```

Hope I provided enough details to investigate this problem.

----------------------
Elastic stack 7.3.0

Contributor guide

Open the contributing guide

Research direction

Start by reproducing the failure with the Filebeat 7.3.0 Docker autodiscover configuration and inspect the harvester log, registry entry, and container log path for container 3252b7646a23293b6728941769f0412e2bd4b74b801ee09ab747c7cdfa74550c. The report names no source file or test; done means identifying why harvesting stops after the container restart and verifying recovery for subsequent log entries.

Written by the indexing model from the issue text.

Assessment

Tech stack
docker
Domain
devops, observability-sre
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.