|
On 07/11/2015 09:29 PM, Burn Alting
wrote:
On Mon, 2015-07-06 at 08:00 -0600, Rich Megginson wrote:
On 07/03/2015 05:49 AM, Burn Alting wrote:
> Has anyone authored code to parse a 389 Directory Server's access.log
> file(s) with an aim of generating audit events based around the LDAP
> request type. Basically, take the log sequence
>
> [21/Apr/2007:11:39:51 -0700] conn=11 fd=608 slot=608 connection from
> 207.1.153.51 to 192.18.122.139
> [21/Apr/2007:11:39:51 -0700] conn=11 op=0 BIND dn="cn=Directory
> Manager" method=128 version=3
> [21/Apr/2007:11:39:51 -0700] conn=11 op=0 RESULT err=0 tag=97
> nentries=0 etime=0
> [21/Apr/2007:11:39:51 -0700] conn=11 op=1 SRCH
> base="dc=example,dc=com" scope=2 filter="(uid=bjensen)"
> [21/Apr/2007:11:39:51 -0700] conn=11 op=1 RESULT err=0 tag=101
> nentries=1 etime=1000 notes=U
> [21/Apr/2007:11:39:51 -0700] conn=11 op=2 UNBIND
> [21/Apr/2007:11:39:51 -0700] conn=11 op=2 fd=608 closed - U1
>
> And turn this into an audit event with
>
> a date/time (21/Apr/2007:11:39:51 -0700), a client location
> (207.1.153.51), server location (192.18.122.139), a user (cn=Directory
> Manager), an event (SRCH) and event metadata of (query -
> base="dc=example,dc=com" scope=2 filter="(uid=bjensen)", result set size
> - 1, timetaken = 1000 sec, etc)
>
> The logconv.pl script seems to do all sorts of analysis, but no event
> representation.
This sounds like a request for a new feature. Would you be able to
write up a description of the new feature based on
http://www.port389.org/docs/389ds/design/design-template.html? If so, I
will post it to the 389 wiki and assign a ticket.
Rich,
Find the write up below.
Regards
Burn Alting
Thanks!
https://fedorahosted.org/389/ticket/48222
http://www.port389.org/docs/389ds/design/audit-events.html
Title
-----
Parse audit-able events from 389/directory server access logs
Overview
--------
A utility is required to parse 389/directory server access logs
whose
output is a well defined record (event) of the LDAP request and
any resultant
responses. Each event would contain the initiating host address
and the
current authenticated DN to make subsequent entity access analysis
more efficient.
In essence, generate a single event for every operation (common
op=) performed
for a unique connection. The events need to be well formed and
consideration given
to further downstream parsing. As the access log records are well
documented,
the output event should minimize changes to the content (if
changed at all).
The utility would need to support time based queries. That is,
generate
events between a given start and end time. Note that if the
connection
and authentication occurs BEFORE the given start time, this detail
still needs to decorate the event output.
The utility would need to indicate if the authenticated DN or
initiating
client could not be ascertained. That is, the information is NOT
in the
file(s) processed.
Optionally can ignore internal operations.
Use Cases
---------
The following cases show a logfile extract and resultant parsed
output.
The output is in XML. Other well formed and parsable output could
be
chosen (eg json) - the intent is that downstream capability needs
to
parse the information.
#1
Extract:
[21/Apr/2009:11:39:51 -0700] conn=11 fd=608 slot=608 connection
from 207.1.153.57 to 192.18.122.139
[21/Apr/2009:11:39:51 -0700] conn=11 op=0 BIND dn="cn=Directory
Manager" method=128 version=3
[21/Apr/2009:11:39:51 -0700] conn=11 op=0 RESULT err=0 tag=97
nentries=0 etime=0
[21/Apr/2009:11:39:51 -0700] conn=11 op=1 SRCH
base="dc=example,dc=com" scope=2 filter="(mobile=+1 123 456-7890)"
[21/Apr/2009:11:39:51 -0700] conn=11 op=1 RESULT err=0 tag=101
nentries=1 etime=3 notes=U
[21/Apr/2009:11:39:51 -0700] conn=11 op=2 UNBIND
[21/Apr/2009:11:39:51 -0700] conn=11 op=2 fd=608 closed - U1
Resultant sub-extract and Event output:
[21/Apr/2009:11:39:51 -0700] conn=11 fd=608 slot=608 connection
from 207.1.153.57 to 192.18.122.139
[21/Apr/2009:11:39:51 -0700] conn=11 op=0 BIND dn="cn=Directory
Manager" method=128 version=3
[21/Apr/2009:11:39:51 -0700] conn=11 op=0 RESULT err=0 tag=97
nentries=0 etime=0
<Event>
<DateTime>21/Apr/2009:11:39:51 -0700</DateTime>
<Client>207.1.153.57</Client>
<Server>192.18.122.139</Server>
<Connection>11</Connection>
<Operation>0</Operation>
<AuthenticatedDN>cn=Directory
Manager</AuthenticatedDN>
<Action>BIND</Action>
<Requests>
<Request>BIND dn="cn=Directory
Manager" method=128 version=3</Request>
</Requests>
<Responses>
<Response>RESULT err=0 tag=97 nentries=0
etime=0</Response>
</Responses>
</Event>
[21/Apr/2009:11:39:51 -0700] conn=11 op=1 SRCH
base="dc=example,dc=com" scope=2 filter="(mobile=+1 123 456-7890)"
[21/Apr/2009:11:39:51 -0700] conn=11 op=1 RESULT err=0 tag=101
nentries=1 etime=3 notes=U
<Event>
<DateTime>21/Apr/2009:11:39:51 -0700</DateTime>
<Client>207.1.153.57</Client>
<Server>192.18.122.139</Server>
<Connection>11</Connection>
<Operation>1</Operation>
<AuthenticatedDN>cn=Directory
Manager</AuthenticatedDN>
<Action>SRCH</Action>
<Requests>
<Request>SRCH base="dc=example,dc=com"
scope=2 filter="(mobile=+1 123
456-7890)"</Request>
</Requests>
<Responses>
<Response>RESULT err=0 tag=101 nentries=1 etime=3
notes=U</Response>
</Responses>
</Event>
[21/Apr/2009:11:39:51 -0700] conn=11 op=2 UNBIND
[21/Apr/2009:11:39:51 -0700] conn=11 op=2 fd=608 closed - U1
<Event>
<DateTime>21/Apr/2009:11:39:51 -0700</DateTime>
<Client>207.1.153.57</Client>
<Server>192.18.122.139</Server>
<Connection>11</Connection>
<Operation>2</Operation>
<AuthenticatedDN>cn=Directory
Manager</AuthenticatedDN>
<Action>UNBIND</Action>
<Requests>
<Request>UNBIND</Request>
</Requests>
<Responses>
<Response>fd=608 closed - U1</Response>
</Responses>
</Event>
#2
Extract:
[07/May/2009:11:43:28 -0700] conn=877 fd=608 slot=608 connection
from 207.1.153.32 to 192.18.122.139
[07/May/2009:11:43:28 -0700] conn=877 op=0 BIND dn="cn=Directory
Manager" method=128 version=3
[07/May/2009:11:43:28 -0700] conn=877 op=0 RESULT err=0 tag=97
nentries=0 etime=0
[07/May/2009:11:43:29 -0700] conn=877 op=1 SRCH base="(ou=People)"
scope=2 filter="(uid=*)"
[07/May/2009:11:43:29 -0700] conn=877 op=1 SORT uid
[07/May/2009:11:43:29 -0700] conn=877 op=1 VLV 0:5:0210 10:5397
(0)
[07/May/2009:11:43:29 -0700] conn=877 op=1 RESULT err=0 tag=101
nentries=1 etime=0
Resultant sub-extract and Event output:
[07/May/2009:11:43:28 -0700] conn=877 fd=608 slot=608 connection
from 207.1.153.32 to 192.18.122.139
[07/May/2009:11:43:28 -0700] conn=877 op=0 BIND dn="cn=Directory
Manager" method=128 version=3
[07/May/2009:11:43:28 -0700] conn=877 op=0 RESULT err=0 tag=97
nentries=0 etime=0
<Event>
<DateTime>07/May/2009:11:43:28 -0700</DateTime>
<Client>207.1.153.32</Client>
<Server>192.18.122.139</Server>
<Connection>877</Connection>
<Operation>0</Operation>
<AuthenticatedDN>cn=Directory
Manager</AuthenticatedDN>
<Action>BIND</Action>
<Requests>
<Request>BIND dn="cn=Directory
Manager" method=128 version=3</Request>
</Requests>
<Responses>
<Response>RESULT err=0 tag=97 nentries=0
etime=0</Response>
</Responses>
</Event>
[07/May/2009:11:43:29 -0700] conn=877 op=1 SRCH base="(ou=People)"
scope=2 filter="(uid=*)"
[07/May/2009:11:43:29 -0700] conn=877 op=1 SORT uid
[07/May/2009:11:43:29 -0700] conn=877 op=1 VLV 0:5:0210 10:5397
(0)
[07/May/2009:11:43:29 -0700] conn=877 op=1 RESULT err=0 tag=101
nentries=1 etime=0
<Event>
<DateTime>07/May/2009:11:43:29 -0700</DateTime>
<Client>207.1.153.32</Client>
<Server>192.18.122.139</Server>
<Connection>877</Connection>
<Operation>1</Operation>
<AuthenticatedDN>cn=Directory
Manager</AuthenticatedDN>
<Action>SRCH</Action>
<Requests>
<Request>SRCH base="(ou=People)"
scope=2 filter="(uid=*)"</Request>
<Request>SORT uid</Request>
<Request>VLV 0:5:0210 10:5397 (0)</Request>
<Responses>
<Response>RESULT err=0 tag=101 nentries=1
etime=0</Response>
</Responses>
</Event>
#3
Extract:
[21/Apr/2009:11:39:55 -0700] conn=14 fd=700 slot=700 connection
from 207.1.153.51 to 192.18.122.139
[21/Apr/2009:11:39:55 -0700] conn=14 op=0 BIND dn="" method=sasl
version=3 mech=DIGEST-MD5
[21/Apr/2009:11:39:55 -0700] conn=14 op=0 RESULT err=14 tag=97
nentries=0 etime=0, SASL bind in progress
[21/Apr/2009:11:39:55 -0700] conn=14 op=1 BIND
dn="uid=jdoe,dc=example,dc=com" method=sasl version=3
mech=DIGEST-MD5
[21/Apr/2009:11:39:55 -0700] conn=14 op=1 RESULT err=0 tag=97
nentries=0 etime=0 dn="uid=jdoe,dc=example,dc=com"
Resultant sub-extract and Event output:
[21/Apr/2009:11:39:55 -0700] conn=14 fd=700 slot=700 connection
from 207.1.153.51 to 192.18.122.139
[21/Apr/2009:11:39:55 -0700] conn=14 op=0 BIND dn="" method=sasl
version=3 mech=DIGEST-MD5
[21/Apr/2009:11:39:55 -0700] conn=14 op=0 RESULT err=14 tag=97
nentries=0 etime=0, SASL bind in progress
<Event>
<DateTime>21/Apr/2009:11:39:53 -0700</DateTime>
<Client>207.1.153.51</Client>
<Server>192.18.122.139</Server>
<Connection>14</Connection>
<Operation>0</Operation>
<AuthenticatedDN>__Anonymous__</AuthenticatedDN>
<Action>BIND</Action>
<Requests>
<Request>BIND dn="" method=sasl
version=3 mech=DIGEST-MD5</Request>
</Requests>
<Responses>
<Response>RESULT err=14 tag=97 nentries=0 etime=0, SASL
bind in progress</Response>
</Responses>
</Event>
[21/Apr/2009:11:39:55 -0700] conn=14 op=1 BIND
dn="uid=jdoe,dc=example,dc=com" method=sasl version=3
mech=DIGEST-MD5
[21/Apr/2009:11:39:55 -0700] conn=14 op=1 RESULT err=0 tag=97
nentries=0 etime=0 dn="uid=jdoe,dc=example,dc=com"
<Event>
<DateTime>21/Apr/2009:11:39:55 -0700</DateTime>
<Client>207.1.153.51</Client>
<Server>192.18.122.139</Server>
<Connection>14</Connection>
<Operation>2</Operation>
<AuthenticatedDN>uid=jdoe,dc=example,dc=com</AuthenticatedDN>
<Action>BIND</Action>
<Requests>
<Request>BIND
dn="uid=jdoe,dc=example,dc=com" method=sasl
version=3 mech=DIGEST-MD5</Request>
</Requests>
<Responses>
<Response>RESULT err=0 tag=97 nentries=0 etime=0
dn="uid=jdoe,dc=example,dc=com"</Response>
</Responses>
</Event>
#4
Extract:
[02/Sep/2014:11:05:56 -0400] conn=35 op=1 fd=64 closed - U1
[02/Sep/2014:11:05:56 -0400] conn=36 fd=64 slot=64 connection from
127.0.0.1 to 127.0.0.1
[02/Sep/2014:11:05:56 -0400] conn=36 op=0 BIND dn="" method=128
version=3
[02/Sep/2014:11:05:56 -0400] conn=36 op=0 RESULT err=0 tag=97
nentries=0 etime=0 dn=""
[02/Sep/2014:11:05:56 -0400] conn=36 op=1 SRCH
base="dc=example,dc=com" scope=2 filter="(uid=scarter)" attrs="c"
[02/Sep/2014:11:05:56 -0400] conn=36 op=1 RESULT err=0 tag=101
nentries=1 etime=0
[02/Sep/2014:11:05:56 -0400] conn=36 op=2 BIND
dn="uid=scarter,ou=people,dc=example,dc=com" method=128 version=3
[02/Sep/2014:11:05:56 -0400] conn=36 op=2 RESULT err=0 tag=97
nentries=0 etime=0 dn="uid=scarter,ou=people,dc=example,dc=com"
[02/Sep/2014:11:05:56 -0400] conn=36 op=3 UNBIND
[02/Sep/2014:11:05:56 -0400] conn=36 op=3 fd=64 closed - U1
Resultant sub-extract and Event output:
[02/Sep/2014:11:05:56 -0400] conn=36 fd=64 slot=64 connection from
127.0.0.1 to 127.0.0.1
[02/Sep/2014:11:05:56 -0400] conn=36 op=0 BIND dn="" method=128
version=3
[02/Sep/2014:11:05:56 -0400] conn=36 op=0 RESULT err=0 tag=97
nentries=0 etime=0 dn=""
<Event>
<DateTime>02/Sep/2014:11:05:56 -0400</DateTime>
<Client>127.0.0.1</Client>
<Server>127.0.0.1</Server>
<Connection>36</Connection>
<Operation>0</Operation>
<AuthenticatedDN>__Anonymous__</AuthenticatedDN>
<Action>BIND</Action>
<Requests>
<Request>BIND dn="" method=128
version=3</Request>
</Requests>
<Responses>
<Response>RESULT err=0 tag=97 nentries=0 etime=0
dn=""</Response>
</Responses>
</Event>
[02/Sep/2014:11:05:56 -0400] conn=36 op=1 SRCH
base="dc=example,dc=com" scope=2 filter="(uid=scarter)" attrs="c"
[02/Sep/2014:11:05:56 -0400] conn=36 op=1 RESULT err=0 tag=101
nentries=1 etime=0
<Event>
<DateTime>02/Sep/2014:11:05:56 -0400</DateTime>
<Client>127.0.0.1</Client>
<Server>127.0.0.1</Server>
<Connection>36</Connection>
<Operation>1</Operation>
<AuthenticatedDN>__Anonymous__</AuthenticatedDN>
<Action>SRCH</Action>
<Requests>
<Request>SRCH base="dc=example,dc=com"
scope=2 filter="(uid=scarter)"
attrs="c"</Request>
</Requests>
<Responses>
<Response>RESULT err=0 tag=101 nentries=1
etime=0</Response>
</Responses>
</Event>
[02/Sep/2014:11:05:56 -0400] conn=36 op=2 BIND
dn="uid=scarter,ou=people,dc=example,dc=com" method=128 version=3
[02/Sep/2014:11:05:56 -0400] conn=36 op=2 RESULT err=0 tag=97
nentries=0 etime=0 dn="uid=scarter,ou=people,dc=example,dc=com"
<Event>
<DateTime>02/Sep/2014:11:05:56 -0400</DateTime>
<Client>127.0.0.1</Client>
<Server>127.0.0.1</Server>
<Connection>36</Connection>
<Operation>2</Operation>
<AuthenticatedDN>uid=scarter,ou=people,dc=example,dc=com</AuthenticatedDN>
<Action>BIND</Action>
<Requests>
<Request>BIND
dn="uid=scarter,ou=people,dc=example,dc=com"
method=128 version=3</Request>
</Requests>
<Responses>
<Response>RESULT err=0 tag=97 nentries=0 etime=0
dn="uid=scarter,ou=people,dc=example,dc=com"</Response>
</Responses>
</Event>
[02/Sep/2014:11:05:56 -0400] conn=36 op=3 UNBIND
[02/Sep/2014:11:05:56 -0400] conn=36 op=3 fd=64 closed - U1
<Event>
<DateTime>02/Sep/2014:11:05:56 -0400</DateTime>
<Client>127.0.0.1</Client>
<Server>127.0.0.1</Server>
<Connection>36</Connection>
<Operation>3</Operation>
<AuthenticatedDN>uid=scarter,ou=people,dc=example,dc=com</AuthenticatedDN>
<Action>UNBIND</Action>
<Requests>
<Request>UNBIND</Request>
</Requests>
<Responses>
<Response>fd=64 closed - U1</Response>
</Responses>
</Event>
Design
------
Assuming an extension to the logconv.pl script
New options:
-A, --audit <ignoreinternal=yes|no>
Default: yes
Generate well formed events of operations found in the access
log(s).
Events will contain the identified connected client address and
authenticated DN performing the operation. Internal
operations,
if logged, will be ignored by default. Specify no to emit events
for internal operations.
Logic flow:
for every "active" connection (ie not closed) maintain a list of
client, server and current authenticated DN.
for every operation for which we have an "active" connection, emit
an event at the close of the operation.
Implementation
--------------
Extend the logconv.pl command as it contains existing access log
file management.
|
