What time do the auditd timestamps represent?

[James Davis]

--
Linux-audit mailing list
Linux-***@redhat.com
https://www.redhat.com/mailman/listinfo/linux-audit

[Paul Moore]

Hi,
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.
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.
----
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?

The kernel captures the time for the timestamp early in the syscall's
invocation, before the syscall actually executes anything. I just
looked quickly at the strace code and it appears it captures the the
timestamp it uses for printing whenever strace.c:printleader() is
called. Considering these two timestamp captures are happening at
different times it doesn't surprise me that the times are off
slightly.

I'm also looking quickly at the kernel code, and it appears that there
is a slightly different approach towards calculating the time used by
the audit subsystem (what you see in the audit record) and the
clock_gettime() syscall (what is used by systrace). I'm not a time
expert, but it looks like the audit subsystem uses a more coarse
approach than the clock_gettime() syscall (for performance reasons)
and I suspect that might be another source of the time difference,
although I think the first issue I mentioned is likely to be the
source of more deviation than algorithmic differences.

[Steve Grubb]

Hello,

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.
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.
'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
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?

If I were going to guess, I'd say it's probably because strace is notified on
syscall entry, then you have a context switch back to user space, the call
back is noticed when strace gets scheduled to run again, and then strace
checks time to create its timestamp. All this delay adds up. Audit on the
otherhand timestamps during the syscall and has no scheduler effects because
it is done within the kernel. The event is shipped to user space already time
stamped. I would say that they may occasionally match but it's by chance and
subject to races.

-Steve

[James Davis]

Hi Steve,

Thanks.

Post by Steve Grubb
If I were going to guess, I'd say it's probably because strace is notified on
syscall entry, then you have a context switch back to user space, the call
back is noticed when strace gets scheduled to run again, and then strace
checks time to create its timestamp. All this delay adds up. Audit on the
otherhand timestamps during the syscall and has no scheduler effects because
it is done within the kernel. The event is shipped to user space already time
stamped. I would say that they may occasionally match but it's by chance and
subject to races.

1. Can you clarify: What time does the auditd timestamp 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?

And perhaps more relevant: which clock is being used? See below.

2. Here is another example along the same lines which I cannot explain
using your suggestion of "inconsistent timestamp times".

This time I am getting the timestamps of both close and exit_group from
strace.

strace:

# strace -f -tt dd if=/dev/zero of=/fs1/timestampTest bs=1K count=1 2>&1 |
egrep 'close|exit'
10:51:15.287648 close(3) = 0
10:51:15.287915 close(3) = 0
10:51:15.288578 close(3) = 0
10:51:15.288705 close(3) = 0
10:51:15.289242 close(3) = 0
10:51:15.289492 close(0) = 0
10:51:15.289518 close(1) = 0
10:51:15.289853 close(0) = 0
10:51:15.290244 close(2) = 0
10:51:15.290275 exit_group(0) = ?
10:51:15.290366 +++ exited with 0 +++

auditd:

[***@fin13p 10:52:28 ~] # ausearch --pid 30711 --interpret --start
'10:40:00'
----
type=PATH msg=audit(08/01/2018 10:51:15.284:84314460) : 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 10:51:15.284:84314460) : 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 10:51:15.284:84314460) :
cwd=/ghome/jamiedavis/src
type=EXECVE msg=audit(08/01/2018 10:51:15.284:84314460) : 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 10:51:15.284:84314460) : arch=x86_64
syscall=execve success=yes exit=0 a0=0x7ffc2b98c410 a1=0x7ffc2b98d7a0
a2=0x7ffc2b98d7d0 a3=0x7ffc2b98bf10 items=2 ppid=30708 pid=30711 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 10:51:15.289:84314462) : arch=x86_64
syscall=exit_group a0=EXIT_SUCCESS a1=0x0 a2=0x0 a3=0xffffffffffffff70
items=0 ppid=30708 pid=30711 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

auditd has a timestamp of 10:51:15.289 for the exit_group of the dd
process.

Suppose the timestamp from strace is as early as possible -- before the
syscall is issued.

Post by Steve Grubb
From strace we see that this process issued a close with timestamp (entry,

exit, return to userland, whatever) of 10:51:15.290244.
No matter when this time was collected (before/during/after syscall), the
time of this close should precede the time of the exit_group.
close (10:51:15.290244) had to happen before xit_group (10:51:15.290275).

If close() happened at 15.290, how can auditd record exit_group as having
happened at 15.289?

Is it possible that strace and auditd are using different clocks?

I did some poking around in the strace and auditd (linux-4.18-rc4) sources.
- strace uses clock_gettime(CLOCK_REALTIME) (see strace.c: printleader).
- auditd, if I read aright, calls audit_get_stamp -> current_kernel_time64
-> ktime_get_coarse_real_ts64.
I cannot interpret the behavior of ktime_get_coarse_real_ts64, but perhaps
this uses the same clock as clock_gettime(CLOCK_REALTIME_COARSE)?

So I wonder if the issue is that the clocks used by strace and auditd have
differing accuracy?

Regards,

~Jamie

Jamie Davis
GPFS Functional Verification Test (FVT)
***@us.ibm.com



From: Steve Grubb <***@redhat.com>
To: linux-***@redhat.com
Cc: James Davis <***@us.ibm.com>
Date: 08/01/2018 10:17 AM
Subject: Re: What time do the auditd timestamps represent?

Hello,

Post by Steve Grubb
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.
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.
'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
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?

If I were going to guess, I'd say it's probably because strace is notified
on
syscall entry, then you have a context switch back to user space, the call
back is noticed when strace gets scheduled to run again, and then strace
checks time to create its timestamp. All this delay adds up. Audit on the
otherhand timestamps during the syscall and has no scheduler effects
because
it is done within the kernel. The event is shipped to user space already
time
stamped. I would say that they may occasionally match but it's by chance
and
subject to races.



-Steve