Fix Filestream store GC, entries are now removed when they TTL expires #38488

belimawr · 2024-03-20T15:58:29Z

Proposed commit message

The resources from Filestream registry have a counter to indicate how many 'owners' have got a hold of that resource, this counter was not correctly decremented. Because it never reached zero, no entry was ever removed from the in-memory store and even though the store GC would run periodically, no resource could be removed. That caused the in-memory store to be ever growing and the op: remove never to be seen in the registry log file.

This commit fixes this bug by correctly calling Released in every resource that is retained.

Checklist

My code follows the style guidelines of this project
I have commented my code, particularly in hard-to-understand areas
~~[ ] I have made corresponding changes to the documentation~~
~~[ ] I have made corresponding change to the default configuration files~~
I have added tests that prove my fix is effective or that my feature works
I have added an entry in CHANGELOG.next.asciidoc or CHANGELOG-developer.next.asciidoc.

~~## Author's Checklist~~

How to test this PR locally

1. Create the following configuration file

filebeat.inputs:
  - type: filestream
    id: "PR-38488"
    paths:
      - /tmp/logs/*.log
    
    clean_removed: true
    close.on_state_change.inactive: 1s
    prospector.scanner.check_interval: 1s

filebeat:
  registry:
    cleanup_interval: 5s

output:
  file:
    enabled: true
    codec.json:
      pretty: false
    path: ${path.home}
    filename: "output"
    rotate_on_startup: false

queue.mem:
  flush:
    timeout: 1s
    min_events: 32

filebeat.registry.flush: 1s

logging:
  level: debug
  selectors:
    - input
    - input.filestream
  metrics:
    enabled: false

2. Build and start Filebeat

cd filebeat
go build .
./filebeat -e

3. Create a log file and add some data

mkdir -p /tmp/logs
echo "fist file">> /tmp/log.log

4. Wait a few seconds until the file is harvested

You can check the output file or look the logs for the logs stating the harvester has been closed

{"log.level":"debug","@timestamp":"2024-03-22T14:18:35.465+0100","log.logger":"input.filestream","log.origin":{"function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*logFile).Read","file.name":"filestream/filestream.go","file.line":131},"message":"End of file reached: /tmp/logs/log.log; Backoff now.","service.name":"filebeat","id":"PR-38488","source_file":"filestream::PR-38488::native::142572-34","path":"/tmp/logs/log.log","state-id":"native::142572-34","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2024-03-22T14:18:39.465+0100","log.logger":"input.filestream","log.origin":{"function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*filestream).readFromSource","file.name":"filestream/input.go","file.line":336},"message":"Reader was closed. Closing. Path='/tmp/logs/log.log'","service.name":"filebeat","id":"PR-38488","source_file":"filestream::PR-38488::native::142572-34","path":"/tmp/logs/log.log","state-id":"native::142572-34","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-03-22T14:18:39.465+0100","log.logger":"input.filestream","log.origin":{"function":"github.com/elastic/beats/v7/filebeat/input/filestream/internal/input-logfile.startHarvester.func1","file.name":"input-logfile/harvester.go","file.line":247},"message":"Stopped harvester for file","service.name":"filebeat","id":"PR-38488","source_file":"filestream::PR-38488::native::142572-34","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-03-22T14:18:39.465+0100","log.logger":"input.filestream","log.origin":{"function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*filestream).Run.func1","file.name":"filestream/input.go","file.line":151},"message":"Closing reader of filestream","service.name":"filebeat","id":"PR-38488","source_file":"filestream::PR-38488::native::142572-34","path":"/tmp/logs/log.log","state-id":"native::142572-34","ecs.version":"1.6.0"}

5. Delete the file

rm /tmp/logs/log.log

6. Wait for the store cleanup logs

{"log.level":"debug","@timestamp":"2024-03-22T14:20:00.464+0100","log.logger":"input","log.origin":{"function":"github.com/elastic/beats/v7/filebeat/input/filestream/internal/input-logfile.gcStore","file.name":"input-logfile/clean.go","file.line":67},"message":"Start store cleanup","service.name":"filebeat","input_type":"filestream","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-03-22T14:20:00.464+0100","log.logger":"input","log.origin":{"function":"github.com/elastic/beats/v7/filebeat/input/filestream/internal/input-logfile.gcStore","file.name":"input-logfile/clean.go","file.line":86},"message":"1 entries removed","service.name":"filebeat","input_type":"filestream","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-03-22T14:20:00.464+0100","log.logger":"input","log.origin":{"function":"github.com/elastic/beats/v7/filebeat/input/filestream/internal/input-logfile.gcStore","file.name":"input-logfile/clean.go","file.line":87},"message":"Done store cleanup","service.name":"filebeat","input_type":"filestream","ecs.version":"1.6.0"}

7. Assert that the entry has also been removed from the registy

You should be able to find the following lines in the registry:

{"op":"set","id":4}
{"k":"filestream::PR-38488::native::142572-34","v":{"ttl":0,"updated":[258163407648,1711113513],"cursor":{"offset":11},"meta":{"source":"/tmp/logs/log.log","identifier_name":"native"}}}
{"op":"remove","id":5}
{"k":"filestream::PR-38488::native::142572-34"}

The set operation is setting ttl:0. That is how the entry is "removed" from the registry
The remove operation removes any reference to that state and also removes all in-memory references to the resource pointing to this file.

Related issues

~~## Use cases~~
~~## Screenshots~~
~~## Logs~~

mergify · 2024-03-20T15:59:14Z

This pull request does not have a backport label.
If this is a bug or security fix, could you label this PR @belimawr? 🙏.
For such, you'll need to label your PR with:

The upcoming major version of the Elastic Stack
The upcoming minor version of the Elastic Stack (if you're not pushing a breaking change)

To fixup this pull request, you need to add the backport labels for the needed
branches, such as:

backport-v8./d.0 is the label to automatically backport to the 8./d branch. /d is the digit

elasticmachine · 2024-03-20T18:21:32Z

💚 Build Succeeded

the below badges are clickable and redirect to their specific view in the CI or DOCS

Expand to view the summary

Build stats

Duration: 145 min 6 sec

❕ Flaky test report

No test was executed to be analysed.

🤖 GitHub comments

Expand to view the GitHub comments

To re-run your PR in the CI, just comment with:

/test : Re-trigger the build.
/package : Generate the packages and run the E2E tests.
/beats-tester : Run the installation tests with beats-tester.
run elasticsearch-ci/docs : Re-trigger the docs validation. (use unformatted text in the comment!)

mergify · 2024-03-22T11:19:38Z

This pull request is now in conflicts. Could you fix it? 🙏
To fixup this pull request, you can check out it locally. See documentation: https://help.github.com/articles/checking-out-pull-requests-locally/

git fetch upstream
git checkout -b fix-clean-removed-filestream upstream/fix-clean-removed-filestream
git merge upstream/main
git push upstream fix-clean-removed-filestream

elasticmachine · 2024-03-22T13:29:16Z

Pinging @elastic/elastic-agent (Team:Elastic-Agent)

elasticmachine · 2024-03-22T13:43:08Z

💚 Build Succeeded

Buildkite Build
Commit: 11fa75e

History

💚 Build #2579 succeeded 0786577
💚 Build #2442 succeeded f7304fa

cc @belimawr

elasticmachine · 2024-03-22T13:45:37Z

💚 Build Succeeded

Buildkite Build
Commit: 11fa75e

History

💚 Build #1345 succeeded 0786577
💚 Build #1211 succeeded f7304fa

cc @belimawr

elasticmachine · 2024-03-22T13:50:23Z

💔 Build Failed

Buildkite Build
Commit: 11fa75e

Failed CI Steps

:windows:-family/core-windows-2016 Unit Tests

History

💚 Build #4228 succeeded 0786577
💔 Build #4091 failed f7304fa

cc @belimawr

elasticmachine · 2024-03-22T13:54:54Z

💚 Build Succeeded

Buildkite Build
Commit: 11fa75e

History

💚 Build #1303 succeeded 0786577
💚 Build #1169 succeeded f7304fa

cc @belimawr

elasticmachine · 2024-03-22T13:56:54Z

💚 Build Succeeded

Buildkite Build
Commit: 11fa75e

History

💚 Build #2582 succeeded 0786577
💚 Build #2448 succeeded f7304fa

cc @belimawr

elasticmachine · 2024-03-22T14:02:59Z

💚 Build Succeeded

Buildkite Build
Commit: 11fa75e

History

💚 Build #1738 succeeded 0786577
💚 Build #1604 succeeded f7304fa

cc @belimawr

elasticmachine · 2024-03-22T14:05:35Z

💚 Build Succeeded

Buildkite Build
Commit: 11fa75e

History

💚 Build #1300 succeeded 0786577
💚 Build #1166 succeeded f7304fa

cc @belimawr

elasticmachine · 2024-03-22T14:10:03Z

💚 Build Succeeded

Buildkite Build
Commit: 11fa75e

History

💚 Build #1313 succeeded 0786577
💚 Build #1179 succeeded f7304fa

cc @belimawr

elasticmachine · 2024-03-22T14:11:17Z

💚 Build Succeeded

Buildkite Build
Commit: 11fa75e

History

💚 Build #2871 succeeded 0786577
💚 Build #2738 succeeded f7304fa

cc @belimawr

elasticmachine · 2024-03-22T14:14:16Z

💚 Build Succeeded

Buildkite Build
Commit: 11fa75e

History

💚 Build #3793 succeeded 0786577
💚 Build #3659 succeeded f7304fa

cc @belimawr

rdner · 2024-03-25T12:27:34Z

filebeat/tests/integration/store_test.go

+	filebeat.Stop()
+
+	registryLogFile := filepath.Join(tempDir, "data/registry/filebeat/log.json")
+	readFilestreamRegistryLog(t, registryLogFile, "remove", 10)


Interesting, I thought we never used remove but just updated the TTL field.

Me too and that was the bug! 🤯

The resources were never correctly released, so the gcClean would never for any entry.

They way Filestream registry works is:

Whenever an entry is "removed", its TTL is set to zero.

Periodically the gcStore runs, any resource that is finished is then removed from the in-memory store and have a remove operation added to the log file.

When Find is called, it locks the resource by calling resource.Retain

beats/filebeat/input/filestream/internal/input-logfile/store.go

Lines 428 to 431 in 9fc2160

if resource := s.table[key]; resource != nil && !resource.isDeleted() {

resource.Retain()

return resource

}

, it's the caller's responsibilit to release it by calling Release

beats/filebeat/input/filestream/internal/input-logfile/store.go

Line 465 in 9fc2160

func (r *resource) Release() { r.pending.Dec() }

There were a few places never calling Release 🤦‍♂️, hence Finished

beats/filebeat/input/filestream/internal/input-logfile/store.go

Line 474 in 9fc2160

func (r *resource) Finished() bool { return r.pending.Load() == 0 }

always returned false and nothing was ever removed from the registry. Which made Filebeat never add the op: remove to the registry log file. 🤯 🤯 🤯 🤯 🤯 🤯 🤯 🤯 🤯

CHANGELOG.next.asciidoc

filebeat/input/filestream/internal/input-logfile/clean.go

belimawr · 2024-03-26T08:10:16Z

Changelog updated, rebased onto main to fix merge conflicts, force push.

Filestream keeps a `resource` for each file it is harvesting, this resource gets written to the registry, both in-memory and on-disk. Even when `clean_removed` was enabled the resource would not be fully released and never removed from memory. While that did not affect offset tracking, it would not release memory when it should.

botelastic bot added the needs_team Indicates that the issue/PR needs a Team:* label label Mar 20, 2024

mergify bot assigned belimawr Mar 20, 2024

belimawr added the Team:Elastic-Agent Label for the Agent team label Mar 20, 2024

botelastic bot removed the needs_team Indicates that the issue/PR needs a Team:* label label Mar 20, 2024

belimawr added bug skip-ci Skip the build in the CI but linting labels Mar 22, 2024

belimawr removed the skip-ci Skip the build in the CI but linting label Mar 22, 2024

belimawr force-pushed the fix-clean-removed-filestream branch from 0786577 to 11fa75e Compare March 22, 2024 13:28

belimawr marked this pull request as ready for review March 22, 2024 13:29

belimawr requested a review from a team as a code owner March 22, 2024 13:29

belimawr requested review from ycombinator and faec March 22, 2024 13:29

pierrehilbert requested a review from rdner March 22, 2024 14:28

rdner approved these changes Mar 25, 2024

View reviewed changes

cmacknz reviewed Mar 25, 2024

View reviewed changes

CHANGELOG.next.asciidoc Outdated Show resolved Hide resolved

cmacknz reviewed Mar 25, 2024

View reviewed changes

filebeat/input/filestream/internal/input-logfile/clean.go Show resolved Hide resolved

belimawr force-pushed the fix-clean-removed-filestream branch from 026195a to 96a28f2 Compare March 26, 2024 08:09

belimawr changed the title ~~Release in-memory resources when clean_removed is set~~ Fix Filestream store GC, entries are now removed when they TTL expires Mar 26, 2024

belimawr requested a review from a team as a code owner March 26, 2024 11:35

botelastic bot added the Team:Automation Label for the Observability productivity team label Mar 26, 2024

belimawr force-pushed the fix-clean-removed-filestream branch from a704351 to 510e462 Compare March 26, 2024 19:11

belimawr mentioned this pull request Mar 26, 2024

Fix clean_inactive for Filestream input #38632

Merged

6 tasks

belimawr force-pushed the fix-clean-removed-filestream branch from 510e462 to 31b2b12 Compare March 27, 2024 13:29

belimawr added 6 commits April 8, 2024 10:49

Add tests for store GC

68aa150

Add changelog

8cff7f3

Run mage check and update all necessary files

34e46a5

Apply lint suggestions

962e6bd

Improve changelog entry

73b6eaa

belimawr force-pushed the fix-clean-removed-filestream branch from 31b2b12 to 73b6eaa Compare April 8, 2024 08:49

Remove extra entry from changelog

d16fa0b

belimawr merged commit 8efb366 into elastic:main Apr 9, 2024
186 of 189 checks passed

belimawr mentioned this pull request Jul 12, 2024

Filestream clean_inactive does not work as expected #40178

Closed

rlueckl mentioned this pull request Sep 20, 2024

Issues on duplicates occuring on both 8.14.1 and on 8.14.3 but not on 8.12.2 #40808

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix Filestream store GC, entries are now removed when they TTL expires #38488

Fix Filestream store GC, entries are now removed when they TTL expires #38488

belimawr commented Mar 20, 2024 •

edited

Loading

mergify bot commented Mar 20, 2024

elasticmachine commented Mar 20, 2024 •

edited

Loading

Build stats

mergify bot commented Mar 22, 2024

elasticmachine commented Mar 22, 2024

elasticmachine commented Mar 22, 2024

elasticmachine commented Mar 22, 2024

elasticmachine commented Mar 22, 2024 •

edited

Loading

elasticmachine commented Mar 22, 2024

elasticmachine commented Mar 22, 2024

elasticmachine commented Mar 22, 2024

elasticmachine commented Mar 22, 2024

elasticmachine commented Mar 22, 2024

elasticmachine commented Mar 22, 2024

elasticmachine commented Mar 22, 2024

rdner Mar 25, 2024

belimawr Mar 26, 2024

belimawr commented Mar 26, 2024

	if resource := s.table[key]; resource != nil && !resource.isDeleted() {
	resource.Retain()
	return resource
	}

Fix Filestream store GC, entries are now removed when they TTL expires #38488

Fix Filestream store GC, entries are now removed when they TTL expires #38488

Conversation

belimawr commented Mar 20, 2024 • edited Loading

Proposed commit message

Checklist

How to test this PR locally

1. Create the following configuration file

2. Build and start Filebeat

3. Create a log file and add some data

4. Wait a few seconds until the file is harvested

5. Delete the file

6. Wait for the store cleanup logs

7. Assert that the entry has also been removed from the registy

Related issues

mergify bot commented Mar 20, 2024

elasticmachine commented Mar 20, 2024 • edited Loading

💚 Build Succeeded

Build stats

❕ Flaky test report

🤖 GitHub comments

mergify bot commented Mar 22, 2024

elasticmachine commented Mar 22, 2024

elasticmachine commented Mar 22, 2024

💚 Build Succeeded

History

elasticmachine commented Mar 22, 2024

💚 Build Succeeded

History

elasticmachine commented Mar 22, 2024 • edited Loading

💔 Build Failed

Failed CI Steps

History

elasticmachine commented Mar 22, 2024

💚 Build Succeeded

History

elasticmachine commented Mar 22, 2024

💚 Build Succeeded

History

elasticmachine commented Mar 22, 2024

💚 Build Succeeded

History

elasticmachine commented Mar 22, 2024

💚 Build Succeeded

History

elasticmachine commented Mar 22, 2024

💚 Build Succeeded

History

elasticmachine commented Mar 22, 2024

💚 Build Succeeded

History

elasticmachine commented Mar 22, 2024

💚 Build Succeeded

History

rdner Mar 25, 2024

Choose a reason for hiding this comment

belimawr Mar 26, 2024

Choose a reason for hiding this comment

belimawr commented Mar 26, 2024

belimawr commented Mar 20, 2024 •

edited

Loading

elasticmachine commented Mar 20, 2024 •

edited

Loading

elasticmachine commented Mar 22, 2024 •

edited

Loading