Auditbeat: Fixes for system/socket dataset by adriansr · Pull Request #19033 · elastic/beats

adriansr · 2020-06-08T14:38:44Z

What does this PR do?

Fixes two problems with the system/socket dataset:

A bug in the internal state of the socket dataset that lead to an infinite loop in systems were the kernel aggressively reuses sockets (observed in 2.6 / CentOS/RHEL 6.x).
Socket expiration wasn't working as expected due to it using an uninitialized timestamp: Flows were expiring at every check.

Also fixes other two minor issues:

A flow could be terminated twice by different code paths leading to wrong numFlows calculation and duplicated flows indexed.
Decoupled the status debug log and socket cleanup into separate goroutines so that logging is still performed under high load situations.

Why is it important?

It has been observed that the dataset would use 100% CPU and stop reporting events. During testing it was discovered that socket expiration, a new feature to prevent excessive memory usage, wasn't working as expected.

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.

How to test this PR locally

The infinite loop is easy to trigger in RHEL 6.x by running:

nmap -n -sT 127.0.0.1 -p 1-65535

elasticmachine · 2020-06-08T15:15:14Z

💚 Build Succeeded

Expand to view the summary

Build stats

Build Cause: [Pull request #19033 event]
Start Time: 2020-06-09T13:43:35.683+0000
Duration: 42 min 36 sec

Test stats 🧪

Test	Results
Failed	0
Passed	736
Skipped	176
Total	912

elasticmachine · 2020-06-08T19:27:32Z

Pinging @elastic/siem (Team:SIEM)

andrewstucki

Just for a bit deeper explanation for a bit of posterity sake.

So, it looks like this happens when you get kernel pointer re-use of the sockets after a missed inet_release syscall. Our old clean-up code failed to remove the socket from the socketLRU but overwrote the map lookup value in the underlying sockets map. When the reaper code for cleaning up old sockets then hit, the orphaned record in the socketLRU would be referenced along with its kernel-based pointer which now pointed to a new socket. As a result the reference in the socketLRU would never get removed and would get evaluated again and again via the Peek call in the for loop. The fix works because any time we expire a socket we now also explicitly remove it from the socketLRU (which a socket reference is always added to when the socket is created) and mark it in a closing state.

Does that sound about right? If so, would it be possible to add a simple test for this condition? Basically flow --> missed inet_release --> reused kernel pointer uint64 --> make sure we have the old socket reference in a closing state?

The feature was using socket.closeTime as a reference for expiration, but this timestamp was only set once the socket was closed or expired, so it caused all sockets to expirate every closeTimeout.

adriansr · 2020-06-09T11:13:58Z

@andrewstucki while adding the test I found yet another problem.

It wasn't dealing with socket timeouts properly, see the new commit.

Can you have another look?

andrewstucki

painful 😬 thanks for tracking these down and adding the tests @adriansr

adriansr · 2020-06-09T13:49:08Z

yep, the whole state.go should be rewritten from scratch :D

Fixes two problems with the system/socket dataset: - A bug in the internal state of the socket dataset that lead to an infinite loop in systems were the kernel aggressively reuses sockets (observed in kernel 2.6 / CentOS/RHEL 6.x). - Socket expiration wasn't working as expected due to it using an uninitialized timestamp: Flows were expiring at every check. Also fixes other two minor issues: - A flow could be terminated twice by different code paths leading to wrong numFlows calculation and duplicated flows indexed. - Decoupled the status debug log and socket cleanup into separate goroutines so that logging is still performed under high load situations. (cherry picked from commit 665b67f)

Fixes two problems with the system/socket dataset: - A bug in the internal state of the socket dataset that lead to an infinite loop in systems were the kernel aggressively reuses sockets (observed in kernel 2.6 / CentOS/RHEL 6.x). - Socket expiration wasn't working as expected due to it using an uninitialized timestamp: Flows were expiring at every check. Also fixes other two minor issues: - A flow could be terminated twice by different code paths leading to wrong numFlows calculation and duplicated flows indexed. - Decoupled the status debug log and socket cleanup into separate goroutines so that logging is still performed under high load situations.

ssfxx · 2023-03-16T03:26:04Z

@adriansr auditbeat version 7.17.0 (amd64), libbeat 7.17.0 system/socket Peak CPU Usage 100%+,mean value Cpu Usage 40%+.
The server events 3000+ per minute.
Please help!
Thanks!

…9081) Fixes two problems with the system/socket dataset: - A bug in the internal state of the socket dataset that lead to an infinite loop in systems were the kernel aggressively reuses sockets (observed in kernel 2.6 / CentOS/RHEL 6.x). - Socket expiration wasn't working as expected due to it using an uninitialized timestamp: Flows were expiring at every check. Also fixes other two minor issues: - A flow could be terminated twice by different code paths leading to wrong numFlows calculation and duplicated flows indexed. - Decoupled the status debug log and socket cleanup into separate goroutines so that logging is still performed under high load situations. (cherry picked from commit 9555ff4)

Avoid flows terminating twice

e88a434

botelastic bot added the needs_team Indicates that the issue/PR needs a Team:* label label Jun 8, 2020

adriansr added bug Team:SIEM labels Jun 8, 2020

botelastic bot removed the needs_team Indicates that the issue/PR needs a Team:* label label Jun 8, 2020

adriansr changed the title ~~Socket diag~~ Auditbeat: Fix infinite loop in system/socket dataset Jun 8, 2020

adriansr added 3 commits June 8, 2020 21:16

Fix infinite loop in socket LRU handling

01e5b77

Decouple stats reporting and expirations

9ba9802

changelog entry

82d9026

adriansr force-pushed the socket_diag branch from a6e49bd to 82d9026 Compare June 8, 2020 19:17

adriansr marked this pull request as ready for review June 8, 2020 19:27

adriansr requested a review from a team as a code owner June 8, 2020 19:27

adriansr added the review label Jun 8, 2020

andrewstucki reviewed Jun 8, 2020

View reviewed changes

adriansr added 2 commits June 9, 2020 13:05

Add test for infinite loop fix

c86a5e5

Fix socket expiration

c82c7b2

The feature was using socket.closeTime as a reference for expiration, but this timestamp was only set once the socket was closed or expired, so it caused all sockets to expirate every closeTimeout.

adriansr changed the title ~~Auditbeat: Fix infinite loop in system/socket dataset~~ Auditbeat: Fixes for system/socket dataset Jun 9, 2020

andrewstucki approved these changes Jun 9, 2020

View reviewed changes

Add second issue to changelog

b99c326

adriansr merged commit 665b67f into elastic:master Jun 9, 2020

adriansr deleted the socket_diag branch June 9, 2020 16:05

adriansr mentioned this pull request Jun 9, 2020

Cherry-pick #19033 to 7.x: Auditbeat: Fixes for system/socket dataset #19079

Merged

3 tasks

adriansr added the v7.9.0 label Jun 9, 2020

adriansr mentioned this pull request Jun 9, 2020

Cherry-pick #19033 to 7.8: Auditbeat: Fixes for system/socket dataset #19080

Merged

3 tasks

adriansr added the v7.8.0 label Jun 9, 2020

adriansr mentioned this pull request Jun 9, 2020

Cherry-pick #19033 to 7.7: Auditbeat: Fixes for system/socket dataset #19081

Merged

3 tasks

adriansr added the v7.7.2 label Jun 9, 2020

adriansr mentioned this pull request Jun 17, 2020

Auditbeat 7.7.x Poor Performance: 100%+ CPU Usage with System Module Socket Dataset Enabled #19141

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Auditbeat: Fixes for system/socket dataset#19033

Auditbeat: Fixes for system/socket dataset#19033
adriansr merged 7 commits intoelastic:masterfrom
adriansr:socket_diag

adriansr commented Jun 8, 2020 •

edited

Loading

Uh oh!

elasticmachine commented Jun 8, 2020 •

edited

Loading

Build stats

Test stats 🧪

Uh oh!

elasticmachine commented Jun 8, 2020

Uh oh!

andrewstucki left a comment •

edited

Loading

Uh oh!

adriansr commented Jun 9, 2020

Uh oh!

andrewstucki left a comment

Uh oh!

adriansr commented Jun 9, 2020

Uh oh!

ssfxx commented Mar 16, 2023 •

edited

Loading

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

Conversation

adriansr commented Jun 8, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

What does this PR do?

Why is it important?

Checklist

How to test this PR locally

Uh oh!

elasticmachine commented Jun 8, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

💚 Build Succeeded

Build stats

Test stats 🧪

Uh oh!

elasticmachine commented Jun 8, 2020

Uh oh!

andrewstucki left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

adriansr commented Jun 9, 2020

Uh oh!

andrewstucki left a comment

Choose a reason for hiding this comment

Uh oh!

adriansr commented Jun 9, 2020

Uh oh!

ssfxx commented Mar 16, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

adriansr commented Jun 8, 2020 •

edited

Loading

elasticmachine commented Jun 8, 2020 •

edited

Loading

andrewstucki left a comment •

edited

Loading

ssfxx commented Mar 16, 2023 •

edited

Loading