Auditbeat system/socket fails when started by config reloading

[adriansr]

For confirmed bugs, please report:

• Version: 7.x
• Operating System: Linux
• Discuss Forum URL: n/a
• Steps to Reproduce:

The system/socket dataset is not prepared to be started using the config reloading configuration, even with reload.enabled: false.

The reloader tries to start the dataset twice, probably because the first invocation of Metricset.Run has returned (the method is non-blocking). This causes a collision with kprobe names as the dataset doesn't support more than one instance of it to be running.

This is the offending config:

auditbeat.yml:

# =========================== Modules configuration ============================
auditbeat.config.modules:
  path: modules.d/*.yml
  reload.enabled: false
[...]

modules.d/system.yml:

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

And this is the log output:

2020-08-31T09:41:20.180Z	INFO	[beat]	instance/beat.go:1005	Process info	{"system_info": {"process": {"capabilities": {"inheritable":null,"permitted":["chown","dac_override","dac_read_search","fowner","fsetid","kill","setgid","setuid","setpcap","linux_immutable","net_bind_service","net_broadcast","net_admin","net_raw","ipc_lock","ipc_owner","sys_module","sys_rawio","sys_chroot","sys_ptrace","sys_pacct","sys_admin","sys_boot","sys_nice","sys_resource","sys_time","sys_tty_config","mknod","lease","audit_write","audit_control","setfcap","mac_override","mac_admin","syslog","wake_alarm","block_suspend","audit_read"],"effective":["chown","dac_override","dac_read_search","fowner","fsetid","kill","setgid","setuid","setpcap","linux_immutable","net_bind_service","net_broadcast","net_admin","net_raw","ipc_lock","ipc_owner","sys_module","sys_rawio","sys_chroot","sys_ptrace","sys_pacct","sys_admin","sys_boot","sys_nice","sys_resource","sys_time","sys_tty_config","mknod","lease","audit_write","audit_control","setfcap","mac_override","mac_admin","syslog","wake_alarm","block_suspend","audit_read"],"bounding":["chown","dac_override","dac_read_search","fowner","fsetid","kill","setgid","setuid","setpcap","linux_immutable","net_bind_service","net_broadcast","net_admin","net_raw","ipc_lock","ipc_owner","sys_module","sys_rawio","sys_chroot","sys_ptrace","sys_pacct","sys_admin","sys_boot","sys_nice","sys_resource","sys_time","sys_tty_config","mknod","lease","audit_write","audit_control","setfcap","mac_override","mac_admin","syslog","wake_alarm","block_suspend","audit_read"],"ambient":null}, "cwd": "/vagrant/x-pack/auditbeat", "exe": "/vagrant/x-pack/auditbeat/auditbeat", "name": "auditbeat", "pid": 7202, "ppid": 7201, "seccomp": {"mode":"filter","no_new_privs":true}, "start_time": "2020-08-31T09:41:19.450Z"}}}
2020-08-31T09:41:20.180Z	INFO	instance/beat.go:298	Setup Beat: auditbeat; Version: 8.0.0
2020-08-31T09:41:20.180Z	INFO	[publisher]	pipeline/module.go:93	Dry run mode. All output types except the file based one are disabled.
2020-08-31T09:41:20.181Z	INFO	[publisher]	pipeline/module.go:113	Beat name: ubuntu-bionic
2020-08-31T09:41:20.181Z	INFO	instance/beat.go:449	auditbeat start running.
2020-08-31T09:41:20.181Z	INFO	[monitoring]	log/log.go:118	Starting metrics logging every 30s
2020-08-31T09:41:20.187Z	INFO	[auditd]	auditd/audit_linux.go:106	auditd module is running as euid=0 on kernel=4.15.0-112-generic
2020-08-31T09:41:20.239Z	INFO	[auditd]	auditd/audit_linux.go:133	socket_type=multicast will be used.
2020-08-31T09:41:20.240Z	WARN	[cfgwarn]	host/host.go:184	BETA: The system/host dataset is beta
2020-08-31T09:41:20.241Z	WARN	[cfgwarn]	login/login.go:95	BETA: The system/login dataset is beta
2020-08-31T09:41:20.242Z	WARN	[cfgwarn]	process/process.go:145	BETA: The system/process dataset is beta
2020-08-31T09:41:20.243Z	WARN	[cfgwarn]	user/user.go:232	BETA: The system/user dataset is beta
2020-08-31T09:41:20.244Z	WARN	[cfgwarn]	socket/socket_linux.go:91	BETA: The system/socket dataset is beta.
2020-08-31T09:41:20.266Z	INFO	[socket]	socket/socket_linux.go:231	Setting up system/socket for kernel 4.15.0-112-generic
2020-08-31T09:41:20.355Z	INFO	[socket]	guess/guess.go:258	Running 17 guesses ...
2020-08-31T09:41:23.179Z	INFO	[add_cloud_metadata]	add_cloud_metadata/add_cloud_metadata.go:89	add_cloud_metadata: hosting provider type not detected.
2020-08-31T09:41:36.354Z	INFO	[socket]	guess/guess.go:305	Guessing done after 15.999370508s
2020-08-31T09:41:37.526Z	INFO	cfgfile/reload.go:164	Config reloader started
2020-08-31T09:41:37.536Z	INFO	[auditd]	auditd/audit_linux.go:106	auditd module is running as euid=0 on kernel=4.15.0-112-generic
2020-08-31T09:41:37.538Z	INFO	[auditd]	auditd/audit_linux.go:133	socket_type=multicast will be used.
2020-08-31T09:41:37.547Z	INFO	[auditd]	auditd/audit_linux.go:216	No audit_rules were specified.
2020-08-31T09:41:37.558Z	WARN	[cfgwarn]	host/host.go:184	BETA: The system/host dataset is beta
2020-08-31T09:41:37.558Z	INFO	[file_integrity]	file_integrity/eventreader_fsnotify.go:97	Started fsnotify watcher	{"file_path": ["/bin", "/etc", "/sbin", "/usr/bin", "/usr/local/bin", "/usr/local/sbin", "/usr/sbin"], "recursive": false}
2020-08-31T09:41:37.559Z	WARN	[cfgwarn]	login/login.go:95	BETA: The system/login dataset is beta
2020-08-31T09:41:37.560Z	WARN	[cfgwarn]	process/process.go:145	BETA: The system/process dataset is beta
2020-08-31T09:41:37.561Z	WARN	[cfgwarn]	user/user.go:232	BETA: The system/user dataset is beta
2020-08-31T09:41:37.561Z	WARN	[cfgwarn]	socket/socket_linux.go:91	BETA: The system/socket dataset is beta.
2020-08-31T09:41:37.603Z	INFO	[socket]	socket/socket_linux.go:231	Setting up system/socket for kernel 4.15.0-112-generic
2020-08-31T09:41:37.606Z	ERROR	[reload]	cfgfile/list.go:95	Error creating runner from config: 1 error: system/socket dataset setup failed: unable to delete existing KProbes for group auditbeat_7202: 19 errors: unable to remove kprobe 'p:auditbeat_7202/sys_execve_call SyS_execve path=+0(%di):u64 arg2=+8(%di):u64 arg3=+16(%di):u64 arg4=+24(%di):u64 arg5=+32(%di):u64 arg6=+40(%di):u64 arg7=+48(%di):u64 arg8=+56(%di):u64 arg9=+64(%di):u64 arg10=+72(%di):u64 arg11=+80(%di):u64 arg12=+88(%di):u64 arg13=+96(%di):u64 arg14=+104(%di):u64 arg15=+112(%di):u64 arg16=+120(%di):u64 argptrs=+0(%si):u64 arg18=+8(%si):u64 arg19=+16(%si):u64 arg20=+24(%si):u64 arg21=+32(%si):u64 arg22=+40(%si):u64 param0=+0(+0(%si)):u64 arg24=+8(+0(%si)):u64 arg25=+16(+0(%si)):u64 arg26=+24(+0(%si)):u64 arg27=+32(+0(%si)):u64 arg28=+40(+0(%si)):u64 arg29=+48(+0(%si)):u64 arg30=+56(+0(%si)):u64 arg31=+64(+0(%si)):u64 arg32=+72(+0(%si)):u64 arg33=+80(+0(%si)):u64 arg34=+88(+0(%si)):u64 arg35=+96(+0(%si)):u64 arg36=+104(+0(%si)):u64 arg37=+112(+0(%si)):u64 arg38=+120(+0(%si)):u64 param1=+0(+8(%si)):u64 arg40=+8(+8(%si)):u64 arg41=+16(+8(%si)):u64 arg42=+24(+8(%si)):u64 arg43=+32(+8(%si)):u64 arg44=+40(+8(%si)):u64 arg45=+48(+8(%si)):u64 arg46=+56(+8(%si)):u64 arg47=+64(+8(%si)):u64 arg48=+72(+8(%si)):u64 arg49=+80(+8(%si)):u64 arg50=+88(+8(%si)):u64 arg51=+96(+8(%si)):u64 arg52=+104(+8(%si)):u64 arg53=+112(+8(%si)):u64 arg54=+120(+8(%si)):u64 param2=+0(+16(%si)):u64 arg56=+8(+16(%si)):u64 arg57=+16(+16(%si)):u64 arg58=+24(+16(%si)):u64 arg59=+32(+16(%si)):u64 arg60=+40(+16(%si)):u64 arg61=+48(+16(%si)):u64 arg62=+56(+16(%si)):u64 arg63=+64(+16(%si)):u64 arg64=+72(+16(%si)):u64 arg65=+80(+16(%si)):u64 arg66=+88(+16(%si)):u64 arg67=+96(+16(%si)):u64 arg68=+104(+16(%si)):u64 arg69=+112(+16(%si)):u64 arg70=+120(+16(%si)):u64 param3=+0(+24(%si)):u64 arg72=+8(+24(%si)):u64 arg73=+16(+24(%si)):u64 arg74=+24(+24(%si)):u64 arg75=+32(+24(%si)):u64 arg76=+40(+24(%si)):u64 arg77=+48(+24(%si)):u64 arg78=+56(+24(%si)):u64 arg79=+64(+24(%si)):u64 arg80=+72(+24(%si)):u64 arg81=+80(+24(%si)):u64 arg82=+88(+24(%si)):u64 arg83=+96(+24(%si)):u64 arg84=+104(+24(%si)):u64 arg85=+112(+24(%si)):u64 arg86=+120(+24(%si)):u64 param4=+0(+32(%si)):u64 arg88=+8(+32(%si)):u64 arg89=+16(+32(%si)):u64 arg90=+24(+32(%si)):u64 arg91=+32(+32(%si)):u64 arg92=+40(+32(%si)):u64 arg93=+48(+32(%si)):u64 arg94=+56(+32(%si)):u64 arg95=+64(+32(%si)):u64 arg96=+72(+32(%si)):u64 arg97=+80(+32(%si)):u64 arg98=+88(+32(%si)):u64 arg99=+96(+32(%si)):u64 arg100=+104(+32(%si)):u64 arg101=+112(+32(%si)):u64 arg102=+120(+32(%si)):u64': write /sys/kernel/debug/tracing/kprobe_events: device or resource busy; unable to remove kprobe 'p:auditbeat_7202/do_exit do_exit ': write /sys/kernel/debug/tracing/kprobe_events: device or resource busy; unable to remove kprobe 'p:auditbeat_7202/commit_creds commit_creds uid=+4(%di):u32 gid=+8(%di):u32 euid=+20(%di):u32 egid=+24(%di):u32': write /sys/kernel/debug/tracing/kprobe_events: device or resource busy; unable to remove kprobe 'p:auditbeat_7202/sock_init_data sock_init_data socket=%di sock=%si': write /sys/kernel/debug/tracing/kprobe_events: device or resource busy; unable to remove kprobe 'p:auditbeat_7202/inet_create inet_create proto=%dx:s32': write /sys/kernel/debug/tracing/kprobe_events: device or resource busy; unable to remove kprobe 'p:auditbeat_7202/inet_release inet_release sock=+32(%di)': write /sys/kernel/debug/tracing/kprobe_events: device or resource busy; unable to remove kprobe 'p:auditbeat_7202/tcp4_connect_in tcp_v4_connect sock=%di laddr=+4(%di):u32 lport=+728(%di):u16 af=+0(%si):u16 addr=+4(%si):u32 port=+2(%si):u16': write /sys/kernel/debug/tracing/kprobe_events: device or resource busy; unable to remove kprobe 'p:auditbeat_7202/ip_local_out_call ip_local_out sock=%si size=+128(%dx):u32 af=+16(%si):u16 laddr=+4(%si):u32 lport=+728(%si):u16 raddr=+0(%si):u32 rport=+12(%si):u16': write /sys/kernel/debug/tracing/kprobe_events: device or resource busy; unable to remove kprobe 'p:auditbeat_7202/tcp_v4_do_rcv_call tcp_v4_do_rcv sock=%di size=+128(%si):u32 laddr=+4(%di):u32 lport=+728(%di):u16 raddr=+0(%di):u32 rport=+12(%di):u16': write /sys/kernel/debug/tracing/kprobe_events: device or resource busy; unable to remove kprobe 'p:auditbeat_7202/udp_sendmsg_in udp_sendmsg sock=%di size=%dx laddr=+4(%di):u32 lport=+728(%di):u16 raddr=+4(+0(%si)):u32 siptr=+0(%si) siaf=+0(+0(%si)):u16 rport=+2(+0(%si)):u16 altraddr=+0(%di):u32 altrport=+12(%di):u16': write /sys/kernel/debug/tracing/kprobe_events: device or resource busy; unable to remove kprobe 'p:auditbeat_7202/udp_queue_rcv_skb udp_queue_rcv_skb sock=%di size=+128(%si):u32 laddr=+4(%di):u32 lport=+728(%di):u16 iphdr=+196(%si):u16 udphdr=+194(%si):u16 base=+208(%si) packet=+0(+208(%si)):u64 arg9=+8(+208(%si)):u64 arg10=+16(+208(%si)):u64 arg11=+24(+208(%si)):u64 arg12=+32(+208(%si)):u64 arg13=+40(+208(%si)):u64 arg14=+48(+208(%si)):u64 arg15=+56(+208(%si)):u64 arg16=+64(+208(%si)):u64 arg17=+72(+208(%si)):u64 arg18=+80(+208(%si)):u64 arg19=+88(+208(%si)):u64 arg20=+96(+208(%si)):u64 arg21=+104(+208(%si)):u64 arg22=+112(+208(%si)):u64 arg23=+120(+208(%si)):u64 arg24=+128(+208(%si)):u64 arg25=+136(+208(%si)):u64 arg26=+144(+208(%si)):u64 arg27=+152(+208(%si)):u64 arg28=+160(+208(%si)):u64 arg29=+168(+208(%si)):u64 arg30=+176(+208(%si)):u64 arg31=+184(+208(%si)):u64 arg32=+192(+208(%si)):u64 arg33=+200(+208(%si)):u64 arg34=+208(+208(%si)):u64 arg35=+216(+208(%si)):u64 arg36=+224(+208(%si)):u64 arg37=+232(+208(%si)):u64 arg38=+240(+208(%si)):u64 arg39=+248(+208(%si)):u64': write /sys/kernel/debug/tracing/kprobe_events: device or resource busy; unable to remove kprobe 'p:auditbeat_7202/clock_sync_probe SyS_newuname magic=+0(%di):u64 timestamp=+8(%di):u64': write /sys/kernel/debug/tracing/kprobe_events: device or resource busy; unable to remove kprobe 'p:auditbeat_7202/inet6_create inet6_create proto=%dx:s32': write /sys/kernel/debug/tracing/kprobe_events: device or resource busy; unable to remove kprobe 'p:auditbeat_7202/inet6_csk_xmit_call inet6_csk_xmit sock=%di size=+128(%si):u32 lport=+728(%di):u16 rport=+12(%di):u16 laddr6a=+72(%di):u64 laddr6b=+80(%di):u64 raddr6a=+56(%di):u64 raddr6b=+64(%di):u64': write /sys/kernel/debug/tracing/kprobe_events: device or resource busy; unable to remove kprobe 'p:auditbeat_7202/tcp_v6_do_rcv_call tcp_v6_do_rcv sock=%di size=+128(%si):u32 lport=+728(%di):u16 rport=+12(%di):u16 laddr6a=+72(%di):u64 laddr6b=+80(%di):u64 raddr6a=+56(%di):u64 raddr6b=+64(%di):u64': write /sys/kernel/debug/tracing/kprobe_events: device or resource busy; unable to remove kprobe 'p:auditbeat_7202/tcp6_connect_in tcp_v6_connect sock=%di laddra=+72(%di):u64 laddrb=+80(%di):u64 lport=+728(%di):u16 af=+0(%si):u16 addra=+8(%si):u64 addrb=+16(%si):u64 port=+2(%si):u16': write /sys/kernel/debug/tracing/kprobe_events: device or resource busy; unable to remove kprobe 'p:auditbeat_7202/udpv6_sendmsg_in udpv6_sendmsg sock=%di size=%dx laddra=+72(%di):u64 laddrb=+80(%di):u64 lport=+728(%di):u16 raddra=+8(+0(%si)):u64 raddrb=+16(+0(%si)):u64 rport=+2(+0(%si)):u16 altraddra=+56(%di):u64 altraddrb=+64(%di):u64 altrport=+12(%di):u16 si6ptr=+0(%si) si6af=+0(+0(%si)):u16': write /sys/kernel/debug/tracing/kprobe_events: device or resource busy; unable to remove kprobe 'p:auditbeat_7202/udpv6_queue_rcv_skb udpv6_queue_rcv_skb sock=%di size=+128(%si):u32 laddra=+72(%di):u64 laddrb=+80(%di):u64 lport=+728(%di):u16 iphdr=+196(%si):u16 udphdr=+194(%si):u16 base=+208(%si) packet=+0(+208(%si)):u64 arg10=+8(+208(%si)):u64 arg11=+16(+208(%si)):u64 arg12=+24(+208(%si)):u64 arg13=+32(+208(%si)):u64 arg14=+40(+208(%si)):u64 arg15=+48(+208(%si)):u64 arg16=+56(+208(%si)):u64 arg17=+64(+208(%si)):u64 arg18=+72(+208(%si)):u64 arg19=+80(+208(%si)):u64 arg20=+88(+208(%si)):u64 arg21=+96(+208(%si)):u64 arg22=+104(+208(%si)):u64 arg23=+112(+208(%si)):u64 arg24=+120(+208(%si)):u64 arg25=+128(+208(%si)):u64 arg26=+136(+208(%si)):u64 arg27=+144(+208(%si)):u64 arg28=+152(+208(%si)):u64 arg29=+160(+208(%si)):u64 arg30=+168(+208(%si)):u64 arg31=+176(+208(%si)):u64 arg32=+184(+208(%si)):u64 arg33=+192(+208(%si)):u64 arg34=+200(+208(%si)):u64 arg35=+208(+208(%si)):u64 arg36=+216(+208(%si)):u64 arg37=+224(+208(%si)):u64 arg38=+232(+208(%si)):u64 arg39=+240(+208(%si)):u64 arg40=+248(+208(%si)):u64': write /sys/kernel/debug/tracing/kprobe_events: device or resource busy; unable to remove kprobe 'p:auditbeat_7202/tcp_sendmsg_in tcp_sendmsg sock=%di size=%dx laddr=+4(%di):u32 lport=+728(%di):u16 raddr=+0(%di):u32 rport=+12(%di):u16 family=+16(%di):u16 laddr6a=+72(%di):u64 laddr6b=+80(%di):u64 raddr6a=+56(%di):u64 raddr6b=+64(%di):u64': write /sys/kernel/debug/tracing/kprobe_events: device or resource busy
2020-08-31T09:41:37.606Z	INFO	cfgfile/reload.go:224	Loading of config files completed.

You can see how the dataset is started first at 2020-08-31T09:41:20.266Z and then a second time at 2020-08-31T09:41:37.603Z.

A workaround is to configure all datasets except socket using config reloader, and configure an instance of the system module with socket enabled in the main auditbeat.yml file.

We should update the socket dataset so that the reloader doesn't try to start more than one instance of it, either by having it's Run method blocking, or keep a global lock that prevents more than one concurrent instance.

[elasticmachine]

Pinging @elastic/siem (Team:SIEM)