Crash when loading the rules

Crash when loading the rules

[Laurent Bigonville]

Hi,

With 2.6.3, when loading the rules, it's crashing and I get the 
following backtrace:

#0  0x00007ffff687e99d in writev () at ../sysdeps/unix/syscall-template.S:84
#1  0x00005555555610ab in dispatch_event (rep=<optimized out>, is_err=0) 
at ../../../src/auditd-dispatch.c:189
#2  0x000055555555a700 in distribute_event (e=0x555555779d80) at 
../../../src/auditd.c:216
#3  0x000055555555aac8 in netlink_handler (loop=<optimized out>, 
io=<optimized out>, revents=<optimized out>) at ../../../src/auditd.c:500
#4  0x0000555555562eb7 in ev_invoke_pending (loop=0x555555773e80 
<default_loop_struct>) at ../../../../src/libev/ev.c:3162
#5  0x000055555556623d in ev_run (loop=0x555555773e80 
<default_loop_struct>, flags=0) at ../../../../src/libev/ev.c:3562
#6  0x0000555555559e06 in ev_loop (flags=0, loop=0x555555773e80 
<default_loop_struct>) at ../../../src/libev/ev.h:835
#7  main (argc=<optimized out>, argv=<optimized out>) at 
../../../src/auditd.c:841

The rules are pretty dump:

-D
-b 8192
-f 1
--backlog_wait_time 0

An idea what's going on?

Cheers,

Laurent Bigonville

Re: Crash when loading the rules

[Steve Grubb]

On Wednesday, July 6, 2016 4:49:58 PM EDT Laurent Bigonville wrote:
> Hi,
> 
> With 2.6.3, when loading the rules, it's crashing and I get the
> following backtrace:
> 
> #0  0x00007ffff687e99d in writev () at ../sysdeps/unix/syscall-template.S:84
> #1  0x00005555555610ab in dispatch_event (rep=<optimized out>, is_err=0) at
> ../../../src/auditd-dispatch.c:189
> #2  0x000055555555a700 in distribute_event (e=0x555555779d80) at
> ../../../src/auditd.c:216
> #3  0x000055555555aac8 in netlink_handler (loop=<optimized out>,
> io=<optimized out>, revents=<optimized out>) at ../../../src/auditd.c:500
> #4  0x0000555555562eb7 in ev_invoke_pending (loop=0x555555773e80
> <default_loop_struct>) at ../../../../src/libev/ev.c:3162
> #5  0x000055555556623d in ev_run (loop=0x555555773e80
> <default_loop_struct>, flags=0) at ../../../../src/libev/ev.c:3562
> #6  0x0000555555559e06 in ev_loop (flags=0, loop=0x555555773e80
> <default_loop_struct>) at ../../../src/libev/ev.h:835
> #7  main (argc=<optimized out>, argv=<optimized out>) at
> ../../../src/auditd.c:841
> 
> The rules are pretty dump:
> 
> -D
> -b 8192
> -f 1
> --backlog_wait_time 0
> 
> An idea what's going on?

By any chance does syslog show that the dispatcher exited due to no active 
plugins?

-Steve

Re: Crash when loading the rules

[Laurent Bigonville]

Le 06/07/16 à 17:23, Steve Grubb a écrit :
> On Wednesday, July 6, 2016 4:49:58 PM EDT Laurent Bigonville wrote:
>> Hi,
>>
>> With 2.6.3, when loading the rules, it's crashing and I get the
>> following backtrace:
>>
>> #0  0x00007ffff687e99d in writev () at ../sysdeps/unix/syscall-template.S:84
>> #1  0x00005555555610ab in dispatch_event (rep=<optimized out>, is_err=0) at
>> ../../../src/auditd-dispatch.c:189
>> #2  0x000055555555a700 in distribute_event (e=0x555555779d80) at
>> ../../../src/auditd.c:216
>> #3  0x000055555555aac8 in netlink_handler (loop=<optimized out>,
>> io=<optimized out>, revents=<optimized out>) at ../../../src/auditd.c:500
>> #4  0x0000555555562eb7 in ev_invoke_pending (loop=0x555555773e80
>> <default_loop_struct>) at ../../../../src/libev/ev.c:3162
>> #5  0x000055555556623d in ev_run (loop=0x555555773e80
>> <default_loop_struct>, flags=0) at ../../../../src/libev/ev.c:3562
>> #6  0x0000555555559e06 in ev_loop (flags=0, loop=0x555555773e80
>> <default_loop_struct>) at ../../../src/libev/ev.h:835
>> #7  main (argc=<optimized out>, argv=<optimized out>) at
>> ../../../src/auditd.c:841
>>
>> The rules are pretty dump:
>>
>> -D
>> -b 8192
>> -f 1
>> --backlog_wait_time 0
>>
>> An idea what's going on?
> By any chance does syslog show that the dispatcher exited due to no active
> plugins?

This is what I see in syslog:

Jul  6 17:25:15 valinor systemd[1]: Starting Security Auditing Service...
Jul  6 17:25:15 valinor auditd[604]: Started dispatcher: /sbin/audispd 
pid: 608
Jul  6 17:25:15 valinor audispd: priority_boost_parser called with: 4
Jul  6 17:25:15 valinor audispd: max_restarts_parser called with: 10
Jul  6 17:25:15 valinor audispd: No plugins found, exiting
Jul  6 17:25:15 valinor augenrules[605]: /sbin/augenrules: No change
Jul  6 17:25:15 valinor auditd[604]: Init complete, auditd 2.6.3 
listening for events (startup state enable)
Jul  6 17:25:15 valinor augenrules[605]: No rules
Jul  6 17:25:15 valinor augenrules[605]: enabled 1
Jul  6 17:25:15 valinor augenrules[605]: failure 1
Jul  6 17:25:15 valinor augenrules[605]: pid 604
Jul  6 17:25:15 valinor augenrules[605]: rate_limit 0
Jul  6 17:25:15 valinor augenrules[605]: backlog_limit 8192
Jul  6 17:25:15 valinor augenrules[605]: lost 35778
Jul  6 17:25:15 valinor augenrules[605]: backlog 6
Jul  6 17:25:15 valinor augenrules[605]: backlog_wait_time 0
Jul  6 17:25:15 valinor augenrules[605]: enabled 1
Jul  6 17:25:15 valinor augenrules[605]: failure 1
Jul  6 17:25:15 valinor augenrules[605]: pid 604
Jul  6 17:25:15 valinor augenrules[605]: rate_limit 0
Jul  6 17:25:15 valinor augenrules[605]: backlog_limit 8192
Jul  6 17:25:15 valinor augenrules[605]: lost 35778
Jul  6 17:25:15 valinor augenrules[605]: backlog 7
Jul  6 17:25:15 valinor augenrules[605]: backlog_wait_time 0
Jul  6 17:25:15 valinor augenrules[605]: enabled 1
Jul  6 17:25:15 valinor augenrules[605]: failure 1
Jul  6 17:25:15 valinor augenrules[605]: pid 604
Jul  6 17:25:15 valinor augenrules[605]: rate_limit 0
Jul  6 17:25:15 valinor augenrules[605]: backlog_limit 8192
Jul  6 17:25:15 valinor augenrules[605]: lost 35778
Jul  6 17:25:15 valinor augenrules[605]: backlog 8
Jul  6 17:25:15 valinor augenrules[605]: backlog_wait_time 0
Jul  6 17:25:16 valinor systemd[1]: Started Security Auditing Service.
Jul  6 17:25:16 valinor systemd[1]: Started Process Core Dump (PID 
619/UID 0).
Jul  6 17:25:16 valinor kernel: [20575.773688] audit: netlink_unicast 
sending to audit_pid=604 returned error: -111
Jul  6 17:25:16 valinor systemd[1]: auditd.service: Main process exited, 
code=dumped, status=11/SEGV
Jul  6 17:25:16 valinor systemd[1]: auditd.service: Unit entered failed 
state.
Jul  6 17:25:16 valinor systemd[1]: auditd.service: Failed with result 
'core-dump'.

Re: Crash when loading the rules

[Steve Grubb]

On Wednesday, July 6, 2016 5:26:44 PM EDT Laurent Bigonville wrote:
Hello,

> Le 06/07/16 à 17:23, Steve Grubb a écrit :
> > On Wednesday, July 6, 2016 4:49:58 PM EDT Laurent Bigonville wrote:
> >> With 2.6.3, when loading the rules, it's crashing and I get the
> >> following backtrace:
> >> 
> >> #0  0x00007ffff687e99d in writev () at
> >> ../sysdeps/unix/syscall-template.S:84 #1  0x00005555555610ab in
> >> dispatch_event (rep=<optimized out>, is_err=0) at
> >> ../../../src/auditd-dispatch.c:189
> >> #2  0x000055555555a700 in distribute_event (e=0x555555779d80) at
> >> ../../../src/auditd.c:216
> >> #3  0x000055555555aac8 in netlink_handler (loop=<optimized out>,
> >> io=<optimized out>, revents=<optimized out>) at ../../../src/auditd.c:500
>
> > By any chance does syslog show that the dispatcher exited due to no active
> > plugins?
> 
> This is what I see in syslog:
> 
> Jul  6 17:25:15 valinor systemd[1]: Starting Security Auditing Service...
> Jul  6 17:25:15 valinor auditd[604]: Started dispatcher: /sbin/audispd
> pid: 608
> Jul  6 17:25:15 valinor audispd: priority_boost_parser called with: 4
> Jul  6 17:25:15 valinor audispd: max_restarts_parser called with: 10
> Jul  6 17:25:15 valinor audispd: No plugins found, exiting

OK. When this happens we should get a SIGCHLD which causes the handler to mark 
the writev pipe descriptor as -1. This is checked for on the way to the 
writev. So, maybe there is a race where the descriptor was ok at entry but the 
child process was gone at writev time. This should have resulted in a SIGPIPE 
when does not core dump but does terminate auditd. This can and should be 
fixed.

However, you are getting a core dump. The only thing I can think of is if 
vec[1].iov_base was assigned an invalid address. I tested this and I get 

writev(6, [{"\1\0\0\0\20\0\0\0j\4\0\0\377\0\0\0", 16}, {NULL, 255}], 2) = -1 
EFAULT (Bad address)

which also does not core dump. So, I'm note sure why you are getting a core 
dump. If this is reproducible it might be good to get an strace to see what is 
being handed to writev. Or maybe try it from valgrind to see if that gives 
additional information.

-Steve

> Jul  6 17:25:16 valinor kernel: [20575.773688] audit: netlink_unicast
> sending to audit_pid=604 returned error: -111
> Jul  6 17:25:16 valinor systemd[1]: auditd.service: Main process exited,
> code=dumped, status=11/SEGV
> Jul  6 17:25:16 valinor systemd[1]: auditd.service: Unit entered failed
> state.
> Jul  6 17:25:16 valinor systemd[1]: auditd.service: Failed with result
> 'core-dump'.

Re: Crash when loading the rules

[Steve Grubb]

Hello,

I revceived the strace file which made the email too big for the mail list.
I'm including the important part below.

On Wednesday, July 6, 2016 6:31:00 PM EDT Laurent Bigonville wrote:
> Le 06/07/16 à 18:23, Steve Grubb a écrit :
> >So, I'm note sure why you are getting a
> > core dump. If this is reproducible it might be good to get an strace to see
> > what is being handed to writev. Or maybe try it from valgrind to see if
> > that gives additional information.
> 
> Valgrind is a bit broken in debian unstable due to the compressed debug
> symbols.
> 
> I've attached here the output of strace


[pid  1595] write(4</var/log/audit/audit.log>, "type=SYSCALL msg=audit(1467798264.913:1259): arch=c000003e syscall=47 success=yes exit=267 a0=6 a1=7ffe30a5e630 a2=40000040 a3=ffffffff items=0 ppid=1 pid=1108 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm=\"systemd-journal\" exe=\"/lib/systemd/systemd-journald\" subj=system_u:system_r:syslogd_t:s0 key=(null)\n", 364) = 364
[pid  1595] fstatfs(4</var/log/audit/audit.log>, {f_type=EXT2_SUPER_MAGIC, f_bsize=4096, f_blocks=3838052, f_bfree=1172381, f_bavail=987245, f_files=977280, f_ffree=703441, f_fsid={9930339, 726475040}, f_namelen=255, f_frsize=4096, f_flags=ST_VALID|ST_RELATIME}) = 0

This shows that it made it to write_to_log and then called check_log_file_size

[pid  1595] --- SIGSEGV {si_signo=SIGSEGV, si_code=SEGV_MAPERR, si_addr=0x90430527} ---
[pid  1602] +++ killed by SIGSEGV (core dumped) +++
+++ killed by SIGSEGV (core dumped) +++

The traceback is not accurate. We are somewhere else in the code. I am going
to bet that its crashing on trying to ack because in the netlink path its not
getting set to NULL. I updated svn with a 1 line fix. Can you either pull the
new code from svn and try it or add this patch to your build?

https://fedorahosted.org/audit/changeset/1320/trunk/src/auditd.c

Let me know if this does it.

Thanks,
-Steve

Re: Crash when loading the rules

[Laurent Bigonville]

Le 06/07/16 à 20:13, Steve Grubb a écrit :
> Hello,
>
> I revceived the strace file which made the email too big for the mail list.
> I'm including the important part below.
>
> On Wednesday, July 6, 2016 6:31:00 PM EDT Laurent Bigonville wrote:
>> Le 06/07/16 à 18:23, Steve Grubb a écrit :
>>> So, I'm note sure why you are getting a
>>> core dump. If this is reproducible it might be good to get an strace to see
>>> what is being handed to writev. Or maybe try it from valgrind to see if
>>> that gives additional information.
>> Valgrind is a bit broken in debian unstable due to the compressed debug
>> symbols.
>>
>> I've attached here the output of strace
>
> [pid  1595] write(4</var/log/audit/audit.log>, "type=SYSCALL msg=audit(1467798264.913:1259): arch=c000003e syscall=47 success=yes exit=267 a0=6 a1=7ffe30a5e630 a2=40000040 a3=ffffffff items=0 ppid=1 pid=1108 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm=\"systemd-journal\" exe=\"/lib/systemd/systemd-journald\" subj=system_u:system_r:syslogd_t:s0 key=(null)\n", 364) = 364
> [pid  1595] fstatfs(4</var/log/audit/audit.log>, {f_type=EXT2_SUPER_MAGIC, f_bsize=4096, f_blocks=3838052, f_bfree=1172381, f_bavail=987245, f_files=977280, f_ffree=703441, f_fsid={9930339, 726475040}, f_namelen=255, f_frsize=4096, f_flags=ST_VALID|ST_RELATIME}) = 0
>
> This shows that it made it to write_to_log and then called check_log_file_size
>
> [pid  1595] --- SIGSEGV {si_signo=SIGSEGV, si_code=SEGV_MAPERR, si_addr=0x90430527} ---
> [pid  1602] +++ killed by SIGSEGV (core dumped) +++
> +++ killed by SIGSEGV (core dumped) +++
>
> The traceback is not accurate. We are somewhere else in the code. I am going
> to bet that its crashing on trying to ack because in the netlink path its not
> getting set to NULL. I updated svn with a 1 line fix. Can you either pull the
> new code from svn and try it or add this patch to your build?
>
> https://fedorahosted.org/audit/changeset/1320/trunk/src/auditd.c
>
> Let me know if this does it.

Seems to be OK with that patch,

Thanks

Laurent Bigonville