Re: What time do the auditd timestamps represent?

Here is my general question. I have not found an answer in the auditd docs. auditd records timestamps. What time do these timestamps represent? - After syscall is issued but before any action begins in kernel-space? - During syscall? - After syscall completes but before it returns to userspace? - "Asynchronously"? - Other? I was expecting the answer to be "Sometime during the kernel-space execution of the syscall". I was surprised this morning to find that this does not appear to be the case. Here is an example: 1. I configure auditd to watch the exit_group syscall. # auditctl -l -a always,exit -F arch=b32 -S exit,fork,execve,setpgid,clone,exit_group -F key=foo -a always,exit -F arch=b64 -S clone,fork,execve,exit,setpgid,exit_group -F key=foo 2. I strace a dd process, watching its syscalls to see when it issues exit_group. # strace -tt dd if=/dev/zero of=/fs1/timestampTest bs=1K count=1 2>&1 | egrep 'exit' 09:28:42.829212 exit_group(0) = ? 09:28:42.829278 +++ exited with 0 +++ strace records that the dd process calls exit_group at 42.829. 3. auditd records a slightly different time -- one millisecond off. I found the pid of the strace process and found where it clones the dd process. The dd process had pid 16642. Let's see what auditd has to say about pid 16642. [root@fin13p 09:49:08 ~] # ausearch --pid 16642 --interpret --start '09:00:00' ---- type=PATH msg=audit(08/01/2018 09:28:42.823:84286412) : item=1 name=/lib64/ld-linux-x86-64.so.2 inode=403084422 dev=fd:00 mode=file,755 ouid=root ogid=root rdev=00:00 objtype=NORMAL type=PATH msg=audit(08/01/2018 09:28:42.823:84286412) : item=0 name=/bin/dd inode=269218970 dev=fd:00 mode=file,755 ouid=root ogid=root rdev=00:00 objtype=NORMAL type=CWD msg=audit(08/01/2018 09:28:42.823:84286412) : cwd=/ghome/jamiedavis/src type=EXECVE msg=audit(08/01/2018 09:28:42.823:84286412) : argc=5 a0=dd a1=if=/dev/zero a2=of=/fs1/timestampTest a3=bs=1K a4=count=1 type=SYSCALL msg=audit(08/01/2018 09:28:42.823:84286412) : arch=x86_64 syscall=execve success=yes exit=0 a0=0x7ffe5a2db320 a1=0x7ffe5a2dc6a8 a2=0x7ffe5a2dc6d8 a3=0x7ffe5a2dae20 items=2 ppid=16639 pid=16642 auid=root uid=root gid=root euid=root suid=root fsuid=root egid=root sgid=root fsgid=root tty=pts6 ses=6437 comm=dd exe=/usr/bin/dd key=prov-auditd ---- type=SYSCALL msg=audit(08/01/2018 09:28:42.828:84286414) : arch=x86_64 syscall=exit_group a0=EXIT_SUCCESS a1=0x0 a2=0x0 a3=0xffffffffffffff70 items=0 ppid=16639 pid=16642 auid=root uid=root gid=root euid=root suid=root fsuid=root egid=root sgid=root fsgid=root tty=pts6 ses=6437 comm=dd exe=/usr/bin/dd key=prov-auditd ---------- Here is my specific question: Why does strace say that exit_group was called at 42.829 while auditd says that the time was 42.828?