search

elastic / beats

:tropical_fish: Beats - Lightweight shippers for Elasticsearch & Logstash
https://www.elastic.co/products/beats
Other
12.15k stars 4.91k forks source link

Filebeat stdin input complains about state not finished #17724

Open adriansr opened 4 years ago

adriansr commented 4 years ago

For confirmed bugs, please report:

Running Filebeat with stdin input causes an error to be printed for every message:

2020-04-15T12:34:17.987+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:18.040+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:18.083+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:18.122+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:18.161+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:18.224+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:18.258+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:18.313+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:18.356+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:18.393+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:18.440+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:18.483+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:18.528+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:18.572+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:18.606+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:18.641+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:18.679+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:18.720+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:18.760+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:18.794+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:18.837+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:18.876+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:18.911+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:18.945+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:18.983+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:19.019+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:19.059+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:19.103+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:19.138+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:19.178+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:19.216+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:19.255+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:19.302+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:19.341+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:19.380+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:19.415+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:19.450+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:19.498+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:19.536+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:19.570+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:19.605+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:19.639+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:19.687+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.
2020-04-15T12:34:19.723+0200    ERROR   file/states.go:112  State for  should have been dropped, but couldn't as state is not finished.

Happens either with dry-run (-N) and Elasticsearch output.

elasticmachine commented 4 years ago

Pinging @elastic/integrations-services (Team:Services)

karln-star commented 4 years ago

For confirmed bugs, please report:

Version: 7.7.1/master Operating System: - Discuss Forum URL: - Steps to Reproduce:

Additional info: also happens with input stdin and output logstash.

sdaclin commented 3 years ago

Actually Filebeat-7.3.2 is the last version that isn't broken Something in here should introduce the regression => https://www.elastic.co/guide/en/beats/libbeat/7.4/release-notes-7.4.0.html

fdartayre commented 3 years ago

It's still there in 7.13.0.

aramhakobyan commented 3 years ago

+1

benelgiac commented 3 years ago

+1

rovnyart commented 2 years ago

+1

mbarretta commented 2 years ago

Still happening in 7.15.2

Config:

filebeat.inputs:
  - type: stdin

output.console:
  pretty: true

CLI command: % echo "test\n" | filebeat -c test.yml -once -e

Output:

2021-11-17T16:38:52.737-0500    INFO    instance/beat.go:665    Home path: [/usr/local/Cellar/filebeat/7.15.2] Config path: [/usr/local/etc/filebeat] Data path: [/usr/local/var/lib/filebeat] Logs path: [/usr/local/var/log/filebeat]
2021-11-17T16:38:52.738-0500    INFO    instance/beat.go:673    Beat ID: f3db139f-b039-4792-a036-7ad74fed0d2d
2021-11-17T16:38:52.739-0500    INFO    [beat]  instance/beat.go:1014   Beat info   {"system_info": {"beat": {"path": {"config": "/usr/local/etc/filebeat", "data": "/usr/local/var/lib/filebeat", "home": "/usr/local/Cellar/filebeat/7.15.2", "logs": "/usr/local/var/log/filebeat"}, "type": "filebeat", "uuid": "f3db139f-b039-4792-a036-7ad74fed0d2d"}}}
2021-11-17T16:38:52.740-0500    INFO    [beat]  instance/beat.go:1023   Build info  {"system_info": {"build": {"commit": "fd322dad6ceafec40c84df4d2a0694ea357d16cc", "libbeat": "7.15.2", "time": "2021-11-12T02:23:13.000Z", "version": "7.15.2"}}}
2021-11-17T16:38:52.740-0500    INFO    [beat]  instance/beat.go:1026   Go runtime info {"system_info": {"go": {"os":"darwin","arch":"amd64","max_procs":8,"version":"go1.17.2"}}}
2021-11-17T16:38:52.740-0500    INFO    [beat]  instance/beat.go:1030   Host info   {"system_info": {"host": {"architecture":"x86_64","boot_time":"2021-11-09T13:36:38.449085-05:00","name":"bokonon","ip":["127.0.0.1/8","::1/128","fe80::1/64","fe80::14e7:d063:673f:1d1c/64","192.168.86.35/24","10.243.14.187/20","fe80::2c7f:d5ff:fec9:47b5/64","fccc:e86c:e3d2:e19:8974::1/40","fe80::44f4:9bff:fe48:80ee/64","fe80::44f4:9bff:fe48:80ee/64","fe80::1db9:a16f:249b:6246/64","fe80::8307:5d33:75a0:bbfd/64","fe80::aede:48ff:fe00:1122/64","fe80::1c3b:73a2:dead:7c22/64","192.168.1.155/24"],"kernel_version":"19.6.0","mac":["8c:85:90:79:3e:e2","82:44:b4:00:2c:05","82:44:b4:00:2c:04","82:44:b4:00:2c:01","82:44:b4:00:2c:00","82:44:b4:00:2c:01","2e:7f:d5:c9:47:b5","0e:85:90:79:3e:e2","46:f4:9b:48:80:ee","46:f4:9b:48:80:ee","ac:de:48:00:11:22","58:ef:68:7b:c2:41"],"os":{"type":"macos","family":"darwin","platform":"darwin","name":"Mac OS X","version":"10.15.7","major":10,"minor":15,"patch":7,"build":"19H1519"},"timezone":"EST","timezone_offset_sec":-18000,"id":"0DE208FA-403D-5F80-971F-46B8F9D7D442"}}}
2021-11-17T16:38:52.740-0500    INFO    [beat]  instance/beat.go:1059   Process info    {"system_info": {"process": {"cwd": "/usr/local/etc/filebeat", "exe": "/usr/local/Cellar/filebeat/7.15.2/libexec/bin/filebeat", "name": "filebeat", "pid": 95718, "ppid": 25378, "start_time": "2021-11-17T16:38:52.476-0500"}}}
2021-11-17T16:38:52.740-0500    INFO    instance/beat.go:309    Setup Beat: filebeat; Version: 7.15.2
2021-11-17T16:38:52.741-0500    INFO    [publisher] pipeline/module.go:113  Beat name: bokonon
2021-11-17T16:38:52.742-0500    ERROR   [modules]   fileset/modules.go:131  Not loading modules. Module directory not found: /usr/local/Cellar/filebeat/7.15.2/module
2021-11-17T16:38:52.742-0500    WARN    beater/filebeat.go:178  Filebeat is unable to load the Ingest Node pipelines for the configured modules because the Elasticsearch output is not configured/enabled. If you have already loaded the Ingest Node pipelines or are using Logstash pipelines, you can ignore this warning.
2021-11-17T16:38:52.743-0500    INFO    instance/beat.go:473    filebeat start running.
2021-11-17T16:38:52.744-0500    INFO    [monitoring]    log/log.go:142  Starting metrics logging every 30s
2021-11-17T16:38:52.744-0500    INFO    memlog/store.go:119 Loading data file of '/usr/local/var/lib/filebeat/registry/filebeat' succeeded. Active transaction id=1
2021-11-17T16:38:52.748-0500    INFO    memlog/store.go:124 Finished loading transaction log file for '/usr/local/var/lib/filebeat/registry/filebeat'. Active transaction id=344
2021-11-17T16:38:52.748-0500    WARN    beater/filebeat.go:381  Filebeat is unable to load the Ingest Node pipelines for the configured modules because the Elasticsearch output is not configured/enabled. If you have already loaded the Ingest Node pipelines or are using Logstash pipelines, you can ignore this warning.
2021-11-17T16:38:52.750-0500    INFO    [registrar] registrar/registrar.go:109  States Loaded from registrar: 1
2021-11-17T16:38:52.750-0500    INFO    [crawler]   beater/crawler.go:71    Loading Inputs: 1
2021-11-17T16:38:52.750-0500    INFO    [crawler]   beater/crawler.go:141   Starting input (ID: 16876905907669988323)
2021-11-17T16:38:52.751-0500    INFO    [crawler]   beater/crawler.go:108   Loading and starting Inputs completed. Enabled inputs: 1
2021-11-17T16:38:52.751-0500    INFO    [stdin.harvester]   log/harvester.go:309    Harvester started for file. {"harvester_id": "afdc5a08-f6de-4ff0-bffd-20a102a2ec80"}
2021-11-17T16:38:52.751-0500    INFO    beater/filebeat.go:447  Running filebeat once. Waiting for completion ...
2021-11-17T16:38:52.751-0500    INFO    beater/filebeat.go:449  All data collection completed. Shutting down.
2021-11-17T16:38:52.751-0500    INFO    beater/crawler.go:148   Stopping Crawler
2021-11-17T16:38:52.751-0500    INFO    beater/crawler.go:158   Stopping 1 inputs
2021-11-17T16:38:52.751-0500    INFO    [crawler]   beater/crawler.go:163   Stopping input: 16876905907669988323
2021-11-17T16:38:52.751-0500    INFO    beater/crawler.go:178   Crawler stopped
2021-11-17T16:38:52.751-0500    INFO    [stdin.harvester]   log/harvester.go:338    End of file reached. Closing because close_eof is enabled.  {"harvester_id": "afdc5a08-f6de-4ff0-bffd-20a102a2ec80"}
{
  "@timestamp": "2021-11-17T21:38:52.751Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "_doc",
    "version": "7.15.2"
  },
  "agent": {
    "id": "f3db139f-b039-4792-a036-7ad74fed0d2d",
    "name": "bokonon",
    "type": "filebeat",
    "version": "7.15.2",
    "hostname": "bokonon",
    "ephemeral_id": "a7e346e1-4a45-4318-98be-646a5b0c6e9b"
  },
  "log": {
    "offset": 0,
    "file": {
      "path": ""
    }
  },
  "message": "test",
  "input": {
    "type": "stdin"
  },
  "ecs": {
    "version": "1.11.0"
  },
  "host": {
    "name": "bokonon"
  }
}
2021-11-17T16:38:53.756-0500    ERROR   file/states.go:125  State for  should have been dropped, but couldn't as state is not finished.
2021-11-17T16:38:53.757-0500    INFO    beater/signalwait.go:93 Continue shutdown: All enqueued events being published.
2021-11-17T16:38:53.757-0500    INFO    [registrar] registrar/registrar.go:132  Stopping Registrar
2021-11-17T16:38:53.757-0500    INFO    [registrar] registrar/registrar.go:166  Ending Registrar
2021-11-17T16:38:53.757-0500    INFO    [registrar] registrar/registrar.go:137  Registrar stopped
2021-11-17T16:38:53.767-0500    INFO    [monitoring]    log/log.go:192  Total metrics   {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":55,"time":{"ms":56}},"total":{"ticks":113,"time":{"ms":114},"value":0},"user":{"ticks":58,"time":{"ms":58}}},"info":{"ephemeral_id":"a7e346e1-4a45-4318-98be-646a5b0c6e9b","uptime":{"ms":1104},"version":"7.15.2"},"memstats":{"gc_next":9084976,"memory_alloc":5987624,"memory_sys":21316616,"memory_total":16362240,"rss":37863424},"runtime":{"goroutines":12}},"filebeat":{"events":{"active":0,"added":2,"done":2},"harvester":{"closed":1,"open_files":-1,"running":0,"skipped":0,"started":1},"input":{"log":{"files":{"renamed":0,"truncated":0}}}},"libbeat":{"config":{"module":{"running":0,"starts":0,"stops":0},"reloads":0,"scans":0},"output":{"events":{"acked":1,"active":0,"batches":1,"dropped":0,"duplicates":0,"failed":0,"toomany":0,"total":1},"read":{"bytes":0,"errors":0},"type":"console","write":{"bytes":622,"errors":0}},"pipeline":{"clients":0,"events":{"active":0,"dropped":0,"failed":0,"filtered":1,"published":1,"retry":0,"total":2},"queue":{"acked":1,"max_events":4096}}},"registrar":{"states":{"cleanup":0,"current":2,"update":2},"writes":{"fail":0,"success":1,"total":1}},"system":{"cpu":{"cores":8},"load":{"1":3.6177,"15":3.8735,"5":4.0776,"norm":{"1":0.4522,"15":0.4842,"5":0.5097}}}}}}
2021-11-17T16:38:53.768-0500    INFO    [monitoring]    log/log.go:193  Uptime: 1.10671341s
2021-11-17T16:38:53.768-0500    INFO    [monitoring]    log/log.go:160  Stopping metrics logging.
2021-11-17T16:38:53.768-0500    INFO    instance/beat.go:479    filebeat stopped.

Note the error after the pretty-printed message

elasticmachine commented 2 years ago

Pinging @elastic/elastic-agent-data-plane (Team:Elastic-Agent-Data-Plane)

dabelousov commented 2 years ago

+1, vesion 7.16.2, input container, filebeat is ddosing logging infrastructure by errors

botelastic[bot] commented 1 year ago

Hi! We just realized that we haven't looked into this issue in a while. We're sorry!

We're labeling this issue as Stale to make it hit our filters and make sure we get back to it as soon as possible. In the meantime, it'd be extremely helpful if you could take a look at it as well and confirm its relevance. A simple comment with a nice emoji will be enough :+1. Thank you for your contribution!

mbarretta commented 1 year ago

Still present in 8.7.0

{"log.level":"error","@timestamp":"2023-04-11T09:00:21.730-0400","log.origin":{"file.name":"file/states.go","file.line":125},"message":"State for  should have been dropped, but couldn't as state is not finished.","service.name":"filebeat","ecs.version":"1.6.0"}
botelastic[bot] commented 5 months ago

Hi! We just realized that we haven't looked into this issue in a while. We're sorry!

We're labeling this issue as Stale to make it hit our filters and make sure we get back to it as soon as possible. In the meantime, it'd be extremely helpful if you could take a look at it as well and confirm its relevance. A simple comment with a nice emoji will be enough :+1. Thank you for your contribution!

Thermi commented 3 months ago

Also still present in 8.13.4