Auditbeat - 120% CPU?

ethrbunny · May 29, 2020, 12:01pm

The high CPU usage of this process has been an ongoing issue. Recently I created a portal host for remote workers. Just supposed to be a gateway to move to other machines. 2 CPUs, 4Gb RAM, etc.

Started getting reports of performance problems so I hopped on to look. First thing I notice is that a supposedly 'empty' host was at a load of 2.5. Looking at 'top' I see auditbeat at 120% CPU and holding steady there. After killing this process the load goes back to 0.15 (where I would expect it).

Here's my auditbeat.yml - what am I doing wrong?

auditbeat.modules:
- module: auditd
  audit_rule_files: [ '${path.config}/audit.rules.d/*.conf' ]
  audit_rules: |

- module: file_integrity
  paths:
  - /bin
  - /usr/bin
  - /sbin
  - /usr/sbin
  - /etc
  - /usr/local/bin
- module: system
  datasets:
  state.period: 12h
  user.detect_password_changes: true
  login.wtmp_file_pattern: /var/log/wtmp*
  login.btmp_file_pattern: /var/log/btmp*
  socket.enable_ipv6: false
  processors:
  - drop_event.when.equals.network.direction: outbound
tags: ["auditbeat"]
setup.dashboards.enabled: false
output.kafka:
  hosts: ["kafkahost:9092"]
       
  topic: 'auditbeat.inbound'
  partition.random:
    reachable_only: true
                     
  required_acks: 1
  compression: gzip
processors:
  - add_host_metadata: ~

logging.level: warning

audit.rules.d folder is empty.

ethrbunny · May 29, 2020, 12:03pm

Might have figured it out.

Removed this section:

processors:
  - add_host_metadata: ~

Now the process sits quietly and takes up v little space.

marcus_lhisp · June 4, 2020, 9:22am

Hi ethrbunny,

Does this solved your problem or does it came back by now? I rolled out an deployment of auditbeat in our infrastructure and after some time I had also issues with high CPU usage.

Would be great if you could give me a little follow-up on this.

Thank you!

BenB196 · June 5, 2020, 1:02pm

Also curious about this as I am noticing significant CPU usage on most machines running auditbeat. Whats weird is that if I restart auditbeat, it will stay low CPU usage for a while, they go right back to use 100%-150% CPU.

marcus_lhisp · June 8, 2020, 6:10am

Hi Ben,

I tried to fix it already also by adjusting the processor section in my config. This doesn't solved the problem for me. Also an adjustment of "stare.period" for the different datasets was promising but not very effective. 62 hourse TIME+ in top and reached again 95% and up.

I really don't know what to try else.

BenB196 · June 8, 2020, 1:04pm

Are you running 7.7.0? when I was running 7.6.x, I didn't have this issue, and I'm wondering if they upgraded version is the cause of the issue.

marcus_lhisp · June 9, 2020, 7:28am

Yes I am running 7.7.0 - but for now I've modified my configuration and disabled the 'socket dataset' from the system module. Now it's running stable with low CPU footprint. I planned to use packetbeat in the near future so this is not a loss for me. Hopefully packetbeat runs smoother than that.

Are you using [anything from] the System module? Those are still in Beta. Maybe this can cause issues in some environments. (Hardware/Network-Infrastructure/Storage etc.)

BenB196 · June 9, 2020, 10:43am

Yeah, I'm running the full system module currently. Did you run any of the 6.7.x versions? I think there may be an issue with 7.7.0 that is causing the high CPU as I didn't see it all in 6.7.x. I'm planning on upgrading to 7.7.1 to see if that fixes it, but if not, I may open a git ticket, as this appears to be a performance bug.

marcus_lhisp · June 10, 2020, 6:49am

An upgrade to 7.7.1 is something that I envision too. File an issue in git is a good idea since this module is in Beta and not supported by my Gold subscription as stated in documentation. I would say that we've keep in touch on this.

btnrsec · June 10, 2020, 10:44pm

I am experiencing the same issue with Auditbeat 7.7.1 with the System module. When I disable the Socket portion of the module it works fine otherwise the system's CPU will eventually spike up to 100%+.

This is a shame as this also was not an issue in 7.6.2.

BenB196 · June 11, 2020, 5:28pm

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.

btnrsec · June 12, 2020, 6:01pm

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.

adrisr · June 17, 2020, 9:01am

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.

hazardousmonk · June 20, 2020, 2:03pm

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

mgotechlock · June 21, 2020, 10:51pm

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.

adrisr · June 22, 2020, 4:27pm

@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'

hazardousmonk · June 23, 2020, 9:41pm

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"}

hazardousmonk · June 23, 2020, 9:43pm

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}}}}}}

hazardousmonk · June 23, 2020, 9:53pm

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]

adrisr · June 24, 2020, 9:10am

@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.