Auditbeat - 120% CPU?

I've also just confirmed this as well, as I was able to upgrade to 7.7.1 and am still experiencing the issue. I'll see about opening a ticket on their github. For reference, would you be able to provide the OS and way you installed? I'm seeing the issue on both OpenSUSE 15.x and CentOS 7-8 with the rpm install of auditbeat.

I know I am not the OP, but I am experiencing this issue with Ubuntu 18.04.1 LTS and Ubuntu 16.04.6 LTS, which was installed from APT.

There's an issue with 7.7.0 and 7.7.1 that causes the system/socket dataset to get stuck and use 100% CPU.

It'll be fixed in 7.8.0. For now, disabling the socket dataset fixes the problem.

Here's a patched version of 7.7.0 incorporating the fix for testing purposes:

https://drive.google.com/drive/u/0/folders/1lIU041ekBHBsY0D-aw-uyBW1FgOgCeoW

Can some of you please test it and post your results here?

Edit: 7.8.0 has been released, which includes the fix.

Hello,

I'm on 7.8.0 but I'm still seeing 100% usage within 5 mins of starting auditbeat. Disabling the sockets dataset makes it behave itself. Currently running Debian 9 - fully updated. Any ideas on how we could solve this? Sockets data is rather important for me.

Thank you

I swear I also saw this initially reoccur, but I since commented out the sockets, restarted auditbeat, then uncommented out sockets, restarted auditbeat and now my cpu is perfectly low.

@mgotechlock is it possible that the 7.7.1 service was still running after updating to 7.8.0 and just needed a restart.

@hazardousmonk I tried to reproduce with Debian 9, unsuccessfully. Can you share the logs running with -d socket ? (or logging.selectors: [socket] in auditbeat.yml). Try to have it run at least a couple of minutes after CPU goes 100%.

Also it'll be good to have a cpu profile, running auditbeat with the -httpprof :8888 command-line option and then once it's using 100% CPU, fetch a profile with

wget 'http://localhost:8888/debug/pprof/profile?seconds=30'

Here's the output of the logs - I uncommented the socket logging selector from the auditbeat.ytml file and kept the CPU cooking at 100% for over 10 min. I cannot post the entire log in this message due to the 13k character limit so I will be breaking this post down into two posts.
The startup looked like this

Summary
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.303Z        INFO        [auditd]        auditd/audit_linux.go:133        socket_type=unicast will be used.
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.317Z        WARN        [cfgwarn]        socket/socket_linux.go:87        BETA: The system/socket dataset is beta.
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.322Z        INFO        [socket]        socket/socket_linux.go:227        Setting up system/socket for kernel 4.9.0-11-amd64
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.323Z        DEBUG        [socket]        socket/socket_linux.go:275        IPv6 supported: true
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.324Z        DEBUG        [socket]        socket/socket_linux.go:282        IPv6 enabled: true
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.401Z        DEBUG        [socket]        socket/socket_linux.go:335        Selected kernel function SyS_gettimeofday for SYS_GETTIMEOFDAY
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.402Z        DEBUG        [socket]        socket/socket_linux.go:335        Selected kernel function SyS_newuname for SYS_UNAME
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.402Z        DEBUG        [socket]        socket/socket_linux.go:335        Selected kernel function ip_local_out for IP_LOCAL_OUT
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.403Z        DEBUG        [socket]        socket/socket_linux.go:335        Selected kernel function __skb_recv_datagram for RECV_UDP_DATAGRAM
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.403Z        DEBUG        [socket]        socket/socket_linux.go:335        Selected kernel function SyS_execve for SYS_EXECVE
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.412Z        INFO        [socket]        guess/guess.go:258        Running 17 guesses ...
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.440Z        DEBUG        [socket]        guess/guess.go:287        Guess guess_struct_creds completed: {"STRUCT_CRED_EGID":24,"STRUCT_CRED_EUID":20,"STRUCT_CRED_GID":8,"STRUCT_CRED_UID":4}
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.470Z        DEBUG        [socket]        guess/guess.go:287        Guess guess_inet6_csk_xmit completed: {"INET6_CSK_XMIT_SKBUFF":"%si","INET6_CSK_XMIT_SOCK":"%di"}
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.493Z        DEBUG        [socket]        guess/guess.go:112         --- result of guess_sk_buff_proto run #1: {"SK_BUFF_PROTO":[192]}
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.515Z        DEBUG        [socket]        guess/guess.go:112         --- result of guess_sk_buff_proto run #2: {"SK_BUFF_PROTO":[144,192]}
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.539Z        DEBUG        [socket]        guess/guess.go:112         --- result of guess_sk_buff_proto run #3: {"SK_BUFF_PROTO":[192]}
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.561Z        DEBUG        [socket]        guess/guess.go:112         --- result of guess_sk_buff_proto run #4: {"SK_BUFF_PROTO":[144,192,568]}
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.584Z        DEBUG        [socket]        guess/guess.go:112         --- result of guess_sk_buff_proto run #5: {"SK_BUFF_PROTO":[192]}
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.607Z        DEBUG        [socket]        guess/guess.go:112         --- result of guess_sk_buff_proto run #6: {"SK_BUFF_PROTO":[144,192]}
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.629Z        DEBUG        [socket]        guess/guess.go:112         --- result of guess_sk_buff_proto run #7: {"SK_BUFF_PROTO":[192]}
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.652Z        DEBUG        [socket]        guess/guess.go:112         --- result of guess_sk_buff_proto run #8: {"SK_BUFF_PROTO":[144,192,680]}
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.652Z        DEBUG        [socket]        guess/guess.go:287        Guess guess_sk_buff_proto completed: {"SK_BUFF_PROTO":192}
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.670Z        DEBUG        [socket]        guess/guess.go:287        Guess guess_udp_sendmsg completed: {"UDP_SENDMSG_LEN":"%dx","UDP_SENDMSG_MSG":"%si","UDP_SENDMSG_SOCK":"%di"}
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.694Z        DEBUG        [socket]        guess/guess.go:112         --- result of guess_inet_sock run #1: {"INET_SOCK_LADDR":[4,84,704,832],"INET_SOCK_LPORT":[712,842],"INET_SOCK_RADDR":[0,68,836],"INET_SOCK_RPORT":[12,840]}
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.717Z        DEBUG        [socket]        guess/guess.go:112         --- result of guess_inet_sock run #2: {"INET_SOCK_LADDR":[4,84,704,832],"INET_SOCK_LPORT":[712,842],"INET_SOCK_RADDR":[0,68,836],"INET_SOCK_RPORT":[12,840]}
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.744Z        DEBUG        [socket]        guess/guess.go:112         --- result of guess_inet_sock run #3: {"INET_SOCK_LADDR":[4,84,704,832],"INET_SOCK_LPORT":[712,842],"INET_SOCK_RADDR":[0,68,836],"INET_SOCK_RPORT":[12,840]}
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.767Z        DEBUG        [socket]        guess/guess.go:112         --- result of guess_inet_sock run #4: {"INET_SOCK_LADDR":[4,84,704,832],"INET_SOCK_LPORT":[712,842],"INET_SOCK_RADDR":[0,68,836],"INET_SOCK_RPORT":[12,840]}
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.769Z        DEBUG        [socket]        guess/guess.go:287        Guess guess_inet_sock completed: {"INET_SOCK_LADDR":4,"INET_SOCK_LADDR_LIST":[4,84,704,832],"INET_SOCK_LPORT":712,"INET_SOCK_LPORT_LIST":[712,842],"INET_SOCK_RADDR":0,"INET_SOCK_RADDR_LIST":[0,68,836],"INET_SOCK_RPORT":12,"INET_SOCK_RPORT_LIST":[12,840]}
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.795Z        DEBUG        [socket]        guess/guess.go:287        Guess guess_struct_socket_sk completed: {"SOCKET_SOCK":32}
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.813Z        DEBUG        [socket]        guess/guess.go:287        Guess tcp_sendmsg_guess completed: {"TCP_SENDMSG_LEN":"%dx"}
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.831Z        DEBUG        [socket]        guess/guess.go:287        Guess guess_sockaddr_in completed: {"SOCKADDR_IN_ADDR":4,"SOCKADDR_IN_AF":0,"SOCKADDR_IN_PORT":2}
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.846Z        DEBUG        [socket]        guess/guess.go:287        Guess guess_syscall_args completed: {"SYS_P1":"%di","SYS_P2":"%si","SYS_P3":"%dx","SYS_P4":"%cx","SYS_P5":"%r8","SYS_P6":"%r9"}
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.846Z        DEBUG        [socket]        guess/guess.go:270        Guess guess_deref skipped.
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.877Z        DEBUG        [socket]        guess/guess.go:287        Guess guess_inet_sock_ipv6 completed: {"INET_SOCK_V6_LADDR_A":"+72","INET_SOCK_V6_LADDR_B":"+80","INET_SOCK_V6_LIMIT":56,"INET_SOCK_V6_RADDR_A":"+56","INET_SOCK_V6_RADDR_B":"+64","INET_SOCK_V6_TERM":":u64"}
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.878Z        DEBUG        [socket]        guess/guess.go:121         --- guess_sk_buff_data_ptr run #0
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.907Z        DEBUG        [socket]        guess/guess.go:121         --- guess_sk_buff_data_ptr run #1
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.936Z        DEBUG        [socket]        guess/guess.go:287        Guess guess_sk_buff_data_ptr completed: {"SK_BUFF_HAS_POINTERS":false,"SK_BUFF_HEAD":208,"SK_BUFF_MAC":198,"SK_BUFF_NETWORK":196,"SK_BUFF_TRANSPORT":194}
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.958Z        DEBUG        [socket]        guess/guess.go:287        Guess guess_sockaddr_in6 completed: {"SOCKADDR_IN6_ADDRA":8,"SOCKADDR_IN6_ADDRB":16,"SOCKADDR_IN6_AF":0,"SOCKADDR_IN6_PORT":2}
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.976Z        DEBUG        [socket]        guess/guess.go:287        Guess guess_tcp_sendmsg_sock completed: {"TCP_SENDMSG_SOCK":"%di"}
Jun 23 21:07:35 host auditbeat[32484]: 2020-06-23T21:07:35.994Z        DEBUG        [socket]        guess/guess.go:112         --- result of guess_inet_sock_af run #1: {"INET_SOCK_AF":[16]}
Jun 23 21:07:36 host auditbeat[32484]: 2020-06-23T21:07:36.012Z        DEBUG        [socket]        guess/guess.go:112         --- result of guess_inet_sock_af run #2: {"INET_SOCK_AF":[16]}
Jun 23 21:07:36 host auditbeat[32484]: 2020-06-23T21:07:36.031Z        DEBUG        [socket]        guess/guess.go:112         --- result of guess_inet_sock_af run #3: {"INET_SOCK_AF":[16]}
Jun 23 21:07:36 host auditbeat[32484]: 2020-06-23T21:07:36.050Z        DEBUG        [socket]        guess/guess.go:112         --- result of guess_inet_sock_af run #4: {"INET_SOCK_AF":[16]}
Jun 23 21:07:36 host auditbeat[32484]: 2020-06-23T21:07:36.068Z        DEBUG        [socket]        guess/guess.go:112         --- result of guess_inet_sock_af run #5: {"INET_SOCK_AF":[16]}
Jun 23 21:07:36 host auditbeat[32484]: 2020-06-23T21:07:36.086Z        DEBUG        [socket]        guess/guess.go:112         --- result of guess_inet_sock_af run #6: {"INET_SOCK_AF":[16]}
Jun 23 21:07:36 host auditbeat[32484]: 2020-06-23T21:07:36.104Z        DEBUG        [socket]        guess/guess.go:112         --- result of guess_inet_sock_af run #7: {"INET_SOCK_AF":[16]}
Jun 23 21:07:36 host auditbeat[32484]: 2020-06-23T21:07:36.122Z        DEBUG        [socket]        guess/guess.go:112         --- result of guess_inet_sock_af run #8: {"INET_SOCK_AF":[16]}
Jun 23 21:07:36 host auditbeat[32484]: 2020-06-23T21:07:36.141Z        DEBUG        [socket]        guess/guess.go:112         --- result of guess_inet_sock_af run #9: {"INET_SOCK_AF":[16]}
Jun 23 21:07:36 host auditbeat[32484]: 2020-06-23T21:07:36.159Z        DEBUG        [socket]        guess/guess.go:112         --- result of guess_inet_sock_af run #10: {"INET_SOCK_AF":[16]}
Jun 23 21:07:36 host auditbeat[32484]: 2020-06-23T21:07:36.160Z        DEBUG        [socket]        guess/guess.go:287        Guess guess_inet_sock_af completed: {"INET_SOCK_AF":16}
Jun 23 21:07:36 host auditbeat[32484]: 2020-06-23T21:07:36.189Z        DEBUG        [socket]        guess/guess.go:287        Guess guess_ip_local_out completed: {"IP_LOCAL_OUT_SK_BUFF":"%dx","IP_LOCAL_OUT_SOCK":"%si"}

and after cooking the CPU at 100% for a while these were the logs. It's worth noting that the auditbeat process took a very long time to stop when using systemctl. During this exercise (of logging), the process refused to shutdown once. The process was refusing to terminate even with the 'kill' command as root. I had to use the SIGKILL to stop it.

Summary
Jun 23 21:31:06 host auditbeat[32484]: 2020-06-23T21:31:06.458Z        INFO        [monitoring]        log/log.go:145        Non-zero metrics in the last 30s        {"monitoring": {"metrics": {"auditd":{"received_msgs":34},"beat":{"cpu":{"system":{"ticks":5380,"time":{"ms":280}},"total":{"ticks":1291040,"time":{"ms":25856},"value":1291040},"user":{"ticks":1285660,"time":{"ms":25576}}},"handles":{"limit":{"hard":4096,"soft":1024},"open":40},"info":{"ephemeral_id":"c35e10b7-4c09-4cd9-a939-f77a34421e97","uptime":{"ms":1411271}},"memstats":{"gc_next":15914128,"memory_alloc":16507464,"memory_total":528722600,"rss":1081344},"runtime":{"goroutines":61}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":39,"batches":4,"total":39}},"pipeline":{"clients":8,"events":{"active":0,"published":39,"total":39},"queue":{"acked":39}}},"metricbeat":{"auditd":{"auditd":{"events":6,"success":6}},"system":{"host":{"events":1,"success":1},"user":{"events":32,"success":32}}},"system":{"load":{"1":1.78,"15":0.99,"5":1.29,"norm":{"1":1.78,"15":0.99,"5":1.29}}}}}}
Jun 23 21:31:36 host auditbeat[32484]: 2020-06-23T21:31:36.474Z        INFO        [monitoring]        log/log.go:145        Non-zero metrics in the last 30s        {"monitoring": {"metrics": {"auditd":{"received_msgs":51},"beat":{"cpu":{"system":{"ticks":5620,"time":{"ms":244}},"total":{"ticks":1319960,"time":{"ms":28928},"value":1319960},"user":{"ticks":1314340,"time":{"ms":28684}}},"handles":{"limit":{"hard":4096,"soft":1024},"open":40},"info":{"ephemeral_id":"c35e10b7-4c09-4cd9-a939-f77a34421e97","uptime":{"ms":1441288}},"memstats":{"gc_next":15595952,"memory_alloc":13150280,"memory_total":541558632,"rss":-1687552},"runtime":{"goroutines":61}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":79,"batches":6,"total":79}},"pipeline":{"clients":8,"events":{"active":0,"published":79,"total":79},"queue":{"acked":79}}},"metricbeat":{"auditd":{"auditd":{"events":9,"success":9}},"system":{"process":{"events":70,"success":70}}},"system":{"load":{"1":1.63,"15":1.01,"5":1.31,"norm":{"1":1.63,"15":1.01,"5":1.31}}}}}}
Jun 23 21:32:06 host auditbeat[32484]: 2020-06-23T21:32:06.461Z        INFO        [monitoring]        log/log.go:145        Non-zero metrics in the last 30s        {"monitoring": {"metrics": {"auditd":{"received_msgs":129},"beat":{"cpu":{"system":{"ticks":5670,"time":{"ms":48}},"total":{"ticks":1349660,"time":{"ms":29700},"value":1349660},"user":{"ticks":1343990,"time":{"ms":29652}}},"handles":{"limit":{"hard":4096,"soft":1024},"open":40},"info":{"ephemeral_id":"c35e10b7-4c09-4cd9-a939-f77a34421e97","uptime":{"ms":1471275}},"memstats":{"gc_next":16736688,"memory_alloc":13694536,"memory_total":549902160,"rss":880640},"runtime":{"goroutines":61}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":21,"batches":2,"total":21}},"pipeline":{"clients":8,"events":{"active":0,"published":21,"total":21},"queue":{"acked":21}}},"metricbeat":{"auditd":{"auditd":{"events":21,"success":21}}},"system":{"load":{"1":1.38,"15":1,"5":1.28,"norm":{"1":1.38,"15":1,"5":1.28}}}}}}
Jun 23 21:32:36 host auditbeat[32484]: 2020-06-23T21:32:36.477Z        INFO        [monitoring]        log/log.go:145        Non-zero metrics in the last 30s        {"monitoring": {"metrics": {"auditd":{"received_msgs":7},"beat":{"cpu":{"system":{"ticks":5710,"time":{"ms":40}},"total":{"ticks":1379040,"time":{"ms":29380},"value":1379040},"user":{"ticks":1373330,"time":{"ms":29340}}},"handles":{"limit":{"hard":4096,"soft":1024},"open":40},"info":{"ephemeral_id":"c35e10b7-4c09-4cd9-a939-f77a34421e97","uptime":{"ms":1501291}},"memstats":{"gc_next":16736688,"memory_alloc":14598864,"memory_total":555815640},"runtime":{"goroutines":61}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":1,"batches":1,"total":1}},"pipeline":{"clients":8,"events":{"active":0,"published":1,"total":1},"queue":{"acked":1}}},"metricbeat":{"auditd":{"auditd":{"events":1,"success":1}}},"system":{"load":{"1":1.31,"15":1.01,"5":1.27,"norm":{"1":1.31,"15":1.01,"5":1.27}}}}}}
Jun 23 21:33:06 host auditbeat[32484]: 2020-06-23T21:33:06.463Z        INFO        [monitoring]        log/log.go:145        Non-zero metrics in the last 30s        {"monitoring": {"metrics": {"auditd":{"received_msgs":27},"beat":{"cpu":{"system":{"ticks":5760,"time":{"ms":52}},"total":{"ticks":1408840,"time":{"ms":29796},"value":1408840},"user":{"ticks":1403080,"time":{"ms":29744}}},"handles":{"limit":{"hard":4096,"soft":1024},"open":40},"info":{"ephemeral_id":"c35e10b7-4c09-4cd9-a939-f77a34421e97","uptime":{"ms":1531277}},"memstats":{"gc_next":17286816,"memory_alloc":13684792,"memory_total":562756304,"rss":1114112},"runtime":{"goroutines":61}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":38,"batches":2,"total":38}},"pipeline":{"clients":8,"events":{"active":0,"published":38,"total":38},"queue":{"acked":38}}},"metricbeat":{"auditd":{"auditd":{"events":5,"success":5}},"system":{"host":{"events":1,"success":1},"user":{"events":32,"success":32}}},"system":{"load":{"1":1.25,"15":1.01,"5":1.26,"norm":{"1":1.25,"15":1.01,"5":1.26}}}}}}
Jun 23 21:33:36 host auditbeat[32484]: 2020-06-23T21:33:36.465Z        INFO        [monitoring]        log/log.go:145        Non-zero metrics in the last 30s        {"monitoring": {"metrics": {"auditd":{"received_msgs":102},"beat":{"cpu":{"system":{"ticks":5960,"time":{"ms":192}},"total":{"ticks":1438200,"time":{"ms":29352},"value":1438200},"user":{"ticks":1432240,"time":{"ms":29160}}},"handles":{"limit":{"hard":4096,"soft":1024},"open":40},"info":{"ephemeral_id":"c35e10b7-4c09-4cd9-a939-f77a34421e97","uptime":{"ms":1561279}},"memstats":{"gc_next":14683280,"memory_alloc":10967280,"memory_total":574967768,"rss":-3178496},"runtime":{"goroutines":61}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":74,"batches":5,"total":74}},"pipeline":{"clients":8,"events":{"active":0,"published":74,"total":74},"queue":{"acked":74}}},"metricbeat":{"auditd":{"auditd":{"events":16,"success":16}},"system":{"process":{"events":58,"success":58}}},"system":{"load":{"1":1.21,"15":1.01,"5":1.25,"norm":{"1":1.21,"15":1.01,"5":1.25}}}}}}
Jun 23 21:34:06 host auditbeat[32484]: 2020-06-23T21:34:06.460Z        INFO        [monitoring]        log/log.go:145        Non-zero metrics in the last 30s        {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":6000,"time":{"ms":48}},"total":{"ticks":1467990,"time":{"ms":29804},"value":1467990},"user":{"ticks":1461990,"time":{"ms":29756}}},"handles":{"limit":{"hard":4096,"soft":1024},"open":40},"info":{"ephemeral_id":"c35e10b7-4c09-4cd9-a939-f77a34421e97","uptime":{"ms":1591274}},"memstats":{"gc_next":16350672,"memory_alloc":11550824,"memory_total":581640704,"rss":1347584},"runtime":{"goroutines":61}},"libbeat":{"config":{"module":{"running":0}},"pipeline":{"clients":8,"events":{"active":0}}},"system":{"load":{"1":1.12,"15":1.01,"5":1.22,"norm":{"1":1.12,"15":1.01,"5":1.22}}}}}}
Jun 23 21:34:36 host auditbeat[32484]: 2020-06-23T21:34:36.464Z        INFO        [monitoring]        log/log.go:145        Non-zero metrics in the last 30s        {"monitoring": {"metrics": {"auditd":{"received_msgs":27},"beat":{"cpu":{"system":{"ticks":6070,"time":{"ms":64}},"total":{"ticks":1497380,"time":{"ms":29380},"value":1497380},"user":{"ticks":1491310,"time":{"ms":29316}}},"handles":{"limit":{"hard":4096,"soft":1024},"open":40},"info":{"ephemeral_id":"c35e10b7-4c09-4cd9-a939-f77a34421e97","uptime":{"ms":1621279}},"memstats":{"gc_next":15062128,"memory_alloc":11370384,"memory_total":587632768,"rss":-1171456},"runtime":{"goroutines":61}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":5,"batches":1,"total":5}},"pipeline":{"clients":8,"events":{"active":0,"published":5,"total":5},"queue":{"acked":5}}},"metricbeat":{"auditd":{"auditd":{"events":5,"success":5}}},"system":{"load":{"1":1.07,"15":1.01,"5":1.2,"norm":{"1":1.07,"15":1.01,"5":1.2}}}}}}
Jun 23 21:35:06 host auditbeat[32484]: 2020-06-23T21:35:06.474Z        INFO        [monitoring]        log/log.go:145        Non-zero metrics in the last 30s        {"monitoring": {"metrics": {"auditd":{"received_msgs":102},"beat":{"cpu":{"system":{"ticks":6120,"time":{"ms":48}},"total":{"ticks":1527190,"time":{"ms":29808},"value":1527190},"user":{"ticks":1521070,"time":{"ms":29760}}},"handles":{"limit":{"hard":4096,"soft":1024},"open":40},"info":{"ephemeral_id":"c35e10b7-4c09-4cd9-a939-f77a34421e97","uptime":{"ms":1651287}},"memstats":{"gc_next":15658816,"memory_alloc":11042504,"memory_total":594390552},"runtime":{"goroutines":61}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":16,"batches":1,"total":16}},"pipeline":{"clients":8,"events":{"active":0,"published":16,"total":16},"queue":{"acked":16}}},"metricbeat":{"auditd":{"auditd":{"events":16,"success":16}}},"system":{"load":{"1":1.04,"15":1,"5":1.18,"norm":{"1":1.04,"15":1,"5":1.18}}}}}}
Jun 23 21:35:36 host auditbeat[32484]: 2020-06-23T21:35:36.473Z        INFO        [monitoring]        log/log.go:145        Non-zero metrics in the last 30s        {"monitoring": {"metrics": {"auditd":{"received_msgs":27},"beat":{"cpu":{"system":{"ticks":6340,"time":{"ms":224}},"total":{"ticks":1557000,"time":{"ms":29816},"value":1557000},"user":{"ticks":1550660,"time":{"ms":29592}}},"handles":{"limit":{"hard":4096,"soft":1024},"open":40},"info":{"ephemeral_id":"c35e10b7-4c09-4cd9-a939-f77a34421e97","uptime":{"ms":1681287}},"memstats":{"gc_next":14861408,"memory_alloc":12727328,"memory_total":607077720,"rss":548864},"runtime":{"goroutines":61}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":96,"batches":6,"total":96}},"pipeline":{"clients":8,"events":{"active":0,"published":96,"total":96},"queue":{"acked":96}}},"metricbeat":{"auditd":{"auditd":{"events":5,"success":5}},"system":{"host":{"events":1,"success":1},"process":{"events":58,"success":58},"user":{"events":32,"success":32}}},"system":{"load":{"1":1.02,"15":1,"5":1.16,"norm":{"1":1.02,"15":1,"5":1.16}}}}}}

There were quite a few non-ASCII characters preceding the text below which I've omitted. I do hope this is helpful. Thank you

elastic/beats/v7/x-pack/auditbeat/module/system/socket.(*state).ExpireOlder2O/go/src/github.com/elastic/beats/x-pack/auditbeat/module/system/socket/state.go2Sgithub.com/elastic/beats/v7/x-pack/auditbeat/module/system/socket.(*state).reapLoop2Ugithub.com/elastic/beats/v7/x-pack/auditbeat/module/system/socket.(*socket).Timestamp2^Yruntime.mapaccess2_fast642'/usr/local/go/src/runtime/map_fast64.go2Zgithub.com/elastic/beats/v7/x-pack/auditbeat/module/system/socket.(*state).onSockDestroyed2^Ptime.Time.Before2^^/usr/local/go/src/time/time.go2^Sruntime.bucketShift2 /usr/local/go/src/runtime/map.go2^Rruntime.bucketMask2^Qruntime.aeshash642%/usr/local/go/src/runtime/asm_amd64.s2^Osyscall.Syscall2+/usr/local/go/src/syscall/asm_linux_amd64.s2^Lsyscall.read21/usr/local/go/src/syscall/zsyscall_linux_amd64.go2^Lsyscall.Read2)/usr/local/go/src/syscall/syscall_unix.go2^Xinternal/poll.(*FD).Read2*/usr/local/go/src/internal/poll/fd_unix.go2^Oos.(*File).read2!/usr/local/go/src/os/file_unix.go2^Oos.(*File).Read2^\/usr/local/go/src/os/file.go2^Xbytes.(*Buffer).ReadFrom2!/usr/local/go/src/bytes/buffer.go2^Qio/ioutil.readAll2%/usr/local/go/src/io/ioutil/ioutil.go2^Rio/ioutil.ReadFile2=github.com/elastic/go-sysinfo/providers/linux.(*process).User2f/go/src/github.com/elastic/beats/vendor/github.com/elastic/go-sysinfo/providers/linux/process_linux.go2\github.com/elastic/beats/v7/x-pack/auditbeat/module/system/process.(*MetricSet).getProcesses2R/go/src/github.com/elastic/beats/x-pack/auditbeat/module/system/process/process.go2[github.com/elastic/beats/v7/x-pack/auditbeat/module/system/process.(*MetricSet).reportState2Ugithub.com/elastic/beats/v7/x-pack/auditbeat/module/system/process.(*MetricSet).Fetch2Jgithub.com/elastic/beats/v7/metricbeat/mb/module.(*metricSetWrapper).fetch2@/go/src/github.com/elastic/beats/metricbeat/mb/module/wrapper.go2Zgithub.com/elastic/beats/v7/metricbeat/mb/module.(*metricSetWrapper).startPeriodicFetching2Hgithub.com/elastic/beats/v7/metricbeat/mb/module.(*metricSetWrapper).run2Ggithub.com/elastic/beats/v7/metricbeat/mb/module.(*Wrapper).Start.func12^Obytes.makeSlice2^Tbytes.(*Buffer).grow2^Tbytes.(*Buffer).Grow2^Pruntime.markroot2$/usr/local/go/src/runtime/mgcmark.go2^Oruntime.gcDrain2^\runtime.gcBgMarkWorker.func22 /usr/local/go/src/runtime/mgc.go2^Sruntime.systemstack2^Vruntime.gcBgMarkWorker2^Psyscall.Syscall62^Nsyscall.openat2^Lsyscall.Open2*/usr/local/go/src/syscall/syscall_linux.go2^Pos.openFileNolog2^Kos.OpenFile28github.com/elastic/beats/v7/libbeat/common/file.ReadOpen2B/go/src/github.com/elastic/beats/libbeat/common/file/file_other.go2Jgithub.com/elastic/beats/v7/auditbeat/helper/hasher.(*FileHasher).HashFile2B/go/src/github.com/elastic/beats/auditbeat/helper/hasher/hasher.go2]github.com/elastic/beats/v7/x-pack/auditbeat/module/system/process.(*MetricSet).enrichProcess2^Ucrypto/sha1.blockAVX22//usr/local/go/src/crypto/sha1/sha1block_amd64.s2^Qcrypto/sha1.block20/usr/local/go/src/crypto/sha1/sha1block_amd64.go2ESCcrypto/sha1.(*digest).Write2%/usr/local/go/src/crypto/sha1/sha1.go2^Wio.(*multiWriter).Write2^]/usr/local/go/src/io/multi.go2^Mio.copyBuffer2^Z/usr/local/go/src/io/io.go2^Gio.Copy2Sgithub.com/elastic/beats/v7/x-pack/auditbeat/module/system/socket.(*linkedList).get2Tgithub.com/elastic/beats/v7/x-pack/auditbeat/module/system/socket.(*linkedList).peek2^Kruntime.add2"/usr/local/go/src/runtime/stubs.go2^Nruntime.usleep2+/usr/local/go/src/runtime/sys_linux_amd64.s2^Nruntime.sysmon2!/usr/local/go/src/runtime/proc.go2^Oruntime.mstart12^Nruntime.mstart2]github.com/elastic/beats/v7/x-pack/auditbeat/module/system/process.(*MetricSet).reportChanges2^Msyscall.Fstat2^Yinternal/poll.(*FD).Fstat2^Oos.(*File).Stat2!/usr/local/go/src/os/stat_unix.go2^Gos.Open29github.com/prometheus/procfs/internal/util.ReadFileNoStat2^/go/src/github.com/elastic/beats/vendor/github.com/prometheus/procfs/internal/util/readfile.go2)github.com/prometheus/procfs.Proc.CmdLine2L/go/src/github.com/elastic/beats/vendor/github.com/prometheus/procfs/proc.go2=github.com/elastic/go-sysinfo/providers/linux.(*process).Info2^Rruntime.scanobject2^Mruntime.futex2^Rruntime.futexsleep2%/usr/local/go/src/runtime/os_linux.go2ESCruntime.notetsleep_internal2'/usr/local/go/src/runtime/lock_futex.go2^Sruntime.notetsleepg2^Qruntime.timerproc2!/usr/local/go/src/runtime/time.go2^Pruntime.epollctl2^Truntime.netpollclose2*/usr/local/go/src/runtime/netpoll_epoll.go2^_internal/poll.runtime_pollClose2$/usr/local/go/src/runtime/netpoll.go2^^internal/poll.(*pollDesc).init22/usr/local/go/src/internal/poll/fd_poll_runtime.go2^Xinternal/poll.(*FD).Init2
os.newFile2^Truntime.(*bmap).keys2^Rruntime.arenaIndex2"/usr/local/go/src/runtime/mheap.go2^Wruntime.heapBitsSetType2$/usr/local/go/src/runtime/mbitmap.go2^Pruntime.mallocgc2#/usr/local/go/src/runtime/malloc.go2
^Qruntime.growslice2"/usr/local/go/src/runtime/slice.go2^]syscall.ParseNetlinkRouteAttr2*/usr/local/go/src/syscall/netlink_linux.go2^Rnet.interfaceTable2(/usr/local/go/src/net/interface_linux.go2^Nnet.Interfaces2"/usr/local/go/src/net/interface.go2Jgithub.com/elastic/beats/v7/x-pack/auditbeat/module/system/host.getNetInfo2L/go/src/github.com/elastic/beats/x-pack/auditbeat/module/system/host/host.go2Ggithub.com/elastic/beats/v7/x-pack/auditbeat/module/system/host.getHost2Zgithub.com/elastic/beats/v7/x-pack/auditbeat/module/system/host.(*MetricSet).reportChanges2Rgithub.com/elastic/beats/v7/x-pack/auditbeat/module/system/host.(*MetricSet).Fetch2^Wstrings.(*Builder).grow2$/usr/local/go/src/strings/builder.go2^Wstrings.(*Builder).Grow2^Lstrings.Join2$/usr/local/go/src/strings/strings.go2Mgithub.com/elastic/beats/v7/libbeat/monitoring.(*flatSnapshotVisitor).getName2?/go/src/github.com/elastic/beats/libbeat/monitoring/snapshot.go2Kgithub.com/elastic/beats/v7/libbeat/monitoring.(*flatSnapshotVisitor).OnInt2<github.com/elastic/beats/v7/libbeat/monitoring.(*Uint).Visit2>/go/src/github.com/elastic/beats/libbeat/monitoring/metrics.go2Bgithub.com/elastic/beats/v7/libbeat/monitoring.(*Registry).doVisit2?/go/src/github.com/elastic/beats/libbeat/monitoring/registry.go2@github.com/elastic/beats/v7/libbeat/monitoring.(*Registry).Visit2Bgithub.com/elastic/beats/v7/libbeat/monitoring.CollectFlatSnapshot2Fgithub.com/elastic/beats/v7/libbeat/monitoring/report/log.makeSnapshot2E/go/src/github.com/elastic/beats/libbeat/monitoring/report/log/log.go2Rgithub.com/elastic/beats/v7/libbeat/monitoring/report/log.(*reporter).snapshotLoop2Lgithub.com/elastic/beats/v7/libbeat/monitoring/report/log.MakeReporter.func12"/usr/share/auditbeat/bin/auditbeat2(ec070b5f82670d2cdf50479b70d6e451e33d4b962*/lib/x86_64-linux-gnu/libnss_files-2.24.so2(8adb8c8cdde0e4c3c3babb8874ae69dca15a666a2(/lib/x86_64-linux-gnu/libnss_nis-2.24.so2(ef45880aee9500f422e6aa707df3dd7bd74372f92$/lib/x86_64-linux-gnu/libnsl-2.24.so2(4a32f8b753772c3163c8e960bddfbb6540b43bd32+/lib/x86_64-linux-gnu/libnss_compat-2.24.so2(b3ced56e5f984cf3f1107d8f03fd910aa27d5c152"/lib/x86_64-linux-gnu/libc-2.24.so2(775143e680ff0cd4cd51cce1ce8ca216e635a1d62#/lib/x86_64-linux-gnu/libdl-2.24.so2(db2caeeec37482a98ab1416d0a9afe2944930de92(/lib/x86_64-linux-gnu/libpthread-2.24.so2(16d609487bcc4acbac29a4eaa2dda0d2f56211ec2 /lib/x86_64-linux-gnu/ld-2.24.so2(606df9c355103e82140d513bc7a25a635591c1532^F[vdso]2
[vsyscall]

@hazardousmonk I was expecting that wget will download a file. Maybe your wget works different. Can you add the -O profile argument and upload the profile file in here? I need the whole binary file to analize it.

Also seen userland cpu spinning after a while in auditbeat with socket dataset enabled, will try without as well...

I'm failing to restart auditbeat 7.8.0 with -httpprof :8888 added to the argument list:

DAEMON_ARGS="-httpprof :8888 ..."

root# service auditbeat restart
 * Restarting Auditbeat is a lightweight shipper for audits.
 auditbeat                                                     Error: unknown flag: --httpprof
Usage:
  auditbeat test config [flags]

Flags:
  -h, --help   help for config

Global Flags:
  -E, --E setting=value              Configuration overwrite
  -c, --c string                     Configuration file, relative to path.config (default "auditbeat.yml")
  -d, --d string                     Enable certain debug selectors
  -e, --e                            Log to stderr and disable syslog/file output
      --environment environmentVar   set environment the Beat is run in (default default)
      --path.config string           Configuration path
      --path.data string             Data path
      --path.home string             Home path
      --path.logs string             Logs path
      --plugin pluginList            Load additional plugins
      --strict.perms                 Strict permission checking on config files (default true)
  -v, --v                            Log at INFO level

                                                                                                                           [fail]

This may seem silly but I'm not able to upload a binary here, it's only allowing images. I can host it on another service and link it if you'd like.

You might find a bit of similar info from the metricbeat' system.socket module

1 Like

I upgraded one system running auditbeat 7.6.1 (without socket issue) to auditbeat 7.8.0 and am getting high CPU usage. I had to disable the socket dataset to workaround.

@hazardousmonk you can upload it somewhere else and send it to me via private msg if you prefer.

@btnrsec can you provide a profile as suggested in Auditbeat - 120% CPU? ?

(Im the OP)

Definitely seeing the high CPU usage of auditbeat. Im having to kill it on a regular basis now.

Im running auditbeat-7.8.0-1.x86_64

@ethrbunny @btnrsec @stefws @hazardousmonk @mgotechlock @BenB196

We've identified the issue with 7.8.0 and have a fix PR.

Here's a snapshot build of 7.8.1 with the fix in the above PR:

https://drive.google.com/drive/folders/1V704wdgKaIKCci0aO1Bao8COAHhjKotp?usp=sharing

Can you give it a try (with socket dataset enabled) and share the outcome?

Thanks

I've installed it on a few systems. It will be a few days before I can tell whether it's behaving properly.

1 Like

So far so good.

The auditbeat snapshot seems much better than the original.

7.8.0 is a v problematic release. I have nodes dropping out on a regular basis - something I've never seen before in the years I've been using elastic.

Looking forward to 7.8.1+