Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Remove 'onFilteredOut' and 'onDroppedOnPublish' callback logs #36399

Merged
merged 1 commit into from
Aug 23, 2023

Conversation

belimawr
Copy link
Contributor

Proposed commit message

The 'onFilteredOut' and 'onDroppedOnPublish' callbacks debug logs can cause an infinity loop of log entries being logged over and over again when running under Elastic-Agent. Those log entries are removed to prevent this from happening in the future.

The monitoring Filebeat uses a drop processor to drop its own logs, however if log level is debug the onFilteredOut callback debug log will log all dropped events, because it is done by the monitoring Filebeat, it will be picked up, dropped and logged again, creating this infinity loop.

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

Related issues

## Use cases
## Screenshots
## Logs

@botelastic botelastic bot added the needs_team Indicates that the issue/PR needs a Team:* label label Aug 22, 2023
The 'onFilteredOut' and 'onDroppedOnPublish' callbacks debug logs can
cause an infinity loop of log entries being logged over and over again
when running under Elastic-Agent. Those log entries are removed to
prevent this from happening in the future.

The monitoring Filebeat uses a drop processor to drop its own logs,
however if log level is debug the `onFilteredOut` callback debug log
will log all dropped events, because it is done by the monitoring
Filebeat, it will be picked up, dropped and logged again, creating
this infinity loop.
@belimawr belimawr force-pushed the remove-on-filtered-events-from-logs branch from 099c2ff to 3e9e8e0 Compare August 22, 2023 16:16
@belimawr belimawr added the Team:Elastic-Agent Label for the Agent team label Aug 22, 2023
@mergify
Copy link
Contributor

mergify bot commented Aug 22, 2023

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

@botelastic botelastic bot removed the needs_team Indicates that the issue/PR needs a Team:* label label Aug 22, 2023
@belimawr belimawr marked this pull request as ready for review August 22, 2023 16:16
@belimawr belimawr requested a review from a team as a code owner August 22, 2023 16:16
@belimawr belimawr requested review from rdner and faec August 22, 2023 16:16
@elasticmachine
Copy link
Collaborator

💚 Build Succeeded

the below badges are clickable and redirect to their specific view in the CI or DOCS
Pipeline View Test View Changes Artifacts preview preview

Expand to view the summary

Build stats

  • Start Time: 2023-08-22T16:17:20.197+0000

  • Duration: 71 min 11 sec

Test stats 🧪

Test Results
Failed 0
Passed 28071
Skipped 2015
Total 30086

💚 Flaky test report

Tests succeeded.

🤖 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!)

@@ -203,12 +203,10 @@ func (c *client) onPublished() {
}

func (c *client) onFilteredOut(e beat.Event) {
c.logger.Debugf("Pipeline client receives callback 'onFilteredOut' for event: %+v", e)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not sure I agree with this change. I remember this log line helped in a few SDHs. Is there a way to log it once? The infinite loop you mentioned in the description – is it expected behaviour? Because this change only removes observability of that loop not the loop itself, right?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The fact that we observe every filtered out event is the root cause of the loop I described. Indeed it only happens if Filebeat is collecting it own logs, which is a side effect of the Elastic-Agent aggregating all Beats logs into its own log file.

Another option I see is to check if Filebeat is running under Elastic-Agent before issuing those debug logs. I'm not a huge fan of having different behaviours on this part of the code base based on whether the Beat is running under Elastic-Agent or not, but that is still a valid option.

What do you think?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we count this callbacks somewhere in the periodic metrics? If so, we can remove the log messages, since I see complaints from other users about the flood of these logs.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not that I'm aware of. Not as callbacks called, we do have some metrics for events dropped, I'm not sure about filtered out.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Okay, at least we have it from dropped. LGTM.

@belimawr belimawr merged commit dde4079 into elastic:main Aug 23, 2023
87 checks passed
@belimawr belimawr deleted the remove-on-filtered-events-from-logs branch August 23, 2023 13:30
@pierrehilbert
Copy link
Collaborator

Could we backport this to 8.9 and 8.10?

@belimawr belimawr added backport-v8.9.0 Automated backport with mergify backport-v8.10.0 Automated backport with mergify labels Sep 1, 2023
@belimawr
Copy link
Contributor Author

belimawr commented Sep 1, 2023

Could we backport this to 8.9 and 8.10?

I don't see any reason not to backport ;)

mergify bot pushed a commit that referenced this pull request Sep 1, 2023
The 'onFilteredOut' and 'onDroppedOnPublish' callbacks debug logs can
cause an infinity loop of log entries being logged over and over again
when running under Elastic-Agent. Those log entries are removed to
prevent this from happening in the future.

The monitoring Filebeat uses a drop processor to drop its own logs,
however if log level is debug the `onFilteredOut` callback debug log
will log all dropped events, because it is done by the monitoring
Filebeat, it will be picked up, dropped and logged again, creating
this infinity loop.

(cherry picked from commit dde4079)
mergify bot pushed a commit that referenced this pull request Sep 1, 2023
The 'onFilteredOut' and 'onDroppedOnPublish' callbacks debug logs can
cause an infinity loop of log entries being logged over and over again
when running under Elastic-Agent. Those log entries are removed to
prevent this from happening in the future.

The monitoring Filebeat uses a drop processor to drop its own logs,
however if log level is debug the `onFilteredOut` callback debug log
will log all dropped events, because it is done by the monitoring
Filebeat, it will be picked up, dropped and logged again, creating
this infinity loop.

(cherry picked from commit dde4079)
belimawr added a commit that referenced this pull request Sep 1, 2023
#36487)

The 'onFilteredOut' and 'onDroppedOnPublish' callbacks debug logs can
cause an infinity loop of log entries being logged over and over again
when running under Elastic-Agent. Those log entries are removed to
prevent this from happening in the future.

The monitoring Filebeat uses a drop processor to drop its own logs,
however if log level is debug the `onFilteredOut` callback debug log
will log all dropped events, because it is done by the monitoring
Filebeat, it will be picked up, dropped and logged again, creating
this infinity loop.

(cherry picked from commit dde4079)

Co-authored-by: Tiago Queiroz <tiago.queiroz@elastic.co>
Scholar-Li pushed a commit to Scholar-Li/beats that referenced this pull request Feb 5, 2024
…c#36399)

The 'onFilteredOut' and 'onDroppedOnPublish' callbacks debug logs can
cause an infinity loop of log entries being logged over and over again
when running under Elastic-Agent. Those log entries are removed to
prevent this from happening in the future.

The monitoring Filebeat uses a drop processor to drop its own logs,
however if log level is debug the `onFilteredOut` callback debug log
will log all dropped events, because it is done by the monitoring
Filebeat, it will be picked up, dropped and logged again, creating
this infinity loop.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
backport-v8.9.0 Automated backport with mergify backport-v8.10.0 Automated backport with mergify Team:Elastic-Agent Label for the Agent team
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Elastic Agent monitoring events that are filtered out are logged infinitely when debug logging is enabled.
6 participants