Weird timestamp length constraint in auparse.c

Weird timestamp length constraint in auparse.c

[Santosh Ananthakrishnan]

[-- Attachment #1.1: Type: text/plain, Size: 882 bytes --]

Hi list

auparse breaks if supplied events with timestamps that are less than 10
characters long, including the milliseconds field. This should never happen
in production, but it can make for fairly mysterious output during testing
if you're generating your own timestamp and eventid numbers :-)

I think the issue is in the str2event function:

static int str2event(char *s, au_event_t *e)
{
        char *ptr;
        errno = 0;
        ptr = strchr(s*+10*, ':');
        if (ptr) {
                e->serial = strtoul(ptr+1, NULL, 10);

This function seems to be searching for the colon that splits the timestamp
from the eventId, but it's starting at s+10, instead of just s. The
variable s points to the first byte after the "msg=audit(" prefix. (10 also
happens to be the length of that prefix, which is what made me suspicious
this might not be micro-optimization)

-Santosh

[-- Attachment #1.2: Type: text/html, Size: 1190 bytes --]

[-- Attachment #2: Type: text/plain, Size: 0 bytes --]

Re: Weird timestamp length constraint in auparse.c

[Steve Grubb]

Hello,

On Wednesday, December 09, 2015 06:10:08 PM Santosh Ananthakrishnan wrote:
> auparse breaks if supplied events with timestamps that are less than 10
> characters long, including the milliseconds field. This should never happen
> in production, but it can make for fairly mysterious output during testing
> if you're generating your own timestamp and eventid numbers :-)
> 
> I think the issue is in the str2event function:
> 
> static int str2event(char *s, au_event_t *e)
> {
>         char *ptr;
>         errno = 0;
>         ptr = strchr(s*+10*, ':');
>         if (ptr) {
>                 e->serial = strtoul(ptr+1, NULL, 10);

Yes, this is intentional. Let's look at an event:

type=DAEMON_START msg=audit(1450095206.768:6444):

When str2event is entered, the pointer is at the '1'. The function calling it 
located the parenthesis.


> This function seems to be searching for the colon that splits the timestamp
> from the eventId, but it's starting at s+10, instead of just s. The
> variable s points to the first byte after the "msg=audit(" prefix. (10 also
> happens to be the length of that prefix, which is what made me suspicious
> this might not be micro-optimization)

It also turns out to be the length of the decimal number for time. The reason 
that we can "safely" do this is because the audit project started in 2004. 
There would not be any kernel prior to that which has audit events created by 
the current audit system. If you get the time_t representation for August 
2004, which is the time that the Linux audit mail list was started, you get: 
1091332800. Any time after that would be bigger and longer. When time_t maxes 
out it'll look like:

time_t: 0xFFFFFFFF, dec: 4294967295, date: Sun Feb  7 01:28:15 2106

Its still 10 digits long. So, the idea was to skip over the first 10 characters 
and start looking for the serial number closer to where its going to be in the 
buffer.

I suppose a quick check could be done to make sure we don't have malformed 
records. Is that what you were wanting to see done?

Thanks,
-Steve

Re: Weird timestamp length constraint in auparse.c

[Santosh Ananthakrishnan]

[-- Attachment #1.1: Type: text/plain, Size: 273 bytes --]

I don't think anything needs to be done, a malformed timestamp only causes
that line to be parsed badly. I was wondering if this behavior was
intentional, now that I see it was, I'm happy to leave this as an FYI for
anybody else being lazy with their test case generation.

[-- Attachment #1.2: Type: text/html, Size: 406 bytes --]

[-- Attachment #2: Type: text/plain, Size: 0 bytes --]