[389-users] 389-ds access.log parsing - turning LDAP request type into an audit event

Rich Megginson rmeggins at redhat.com
Mon Jul 13 19:59:14 UTC 2015 

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=&quot;cn=Directory Manager&quot; 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=&quot;dc=example,dc=com&quot; scope=2 
> filter=&quot;(mobile=+1 123 456-7890)&quot;</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=&quot;cn=Directory Manager&quot; 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=&quot;(ou=People)&quot; scope=2 
> filter=&quot;(uid=*)&quot;</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=&quot;&quot; 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=&quot;uid=jdoe,dc=example,dc=com&quot; 
> method=sasl version=3 mech=DIGEST-MD5</Request>
>   </Requests>
>   <Responses>
>     <Response>RESULT err=0 tag=97 nentries=0 etime=0 
> dn=&quot;uid=jdoe,dc=example,dc=com&quot;</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=&quot;&quot; method=128 version=3</Request>
>   </Requests>
>   <Responses>
>     <Response>RESULT err=0 tag=97 nentries=0 etime=0 
> dn=&quot;&quot;</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=&quot;dc=example,dc=com&quot; scope=2 
> filter=&quot;(uid=scarter)&quot; attrs=&quot;c&quot;</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=&quot;uid=scarter,ou=people,dc=example,dc=com&quot; method=128 
> version=3</Request>
>   </Requests>
>   <Responses>
>     <Response>RESULT err=0 tag=97 nentries=0 etime=0 
> dn=&quot;uid=scarter,ou=people,dc=example,dc=com&quot;</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.
>
>
>
>

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.fedoraproject.org/pipermail/389-users/attachments/20150713/b5adce3f/attachment.html>

More information about the 389-users mailing list