January 31, 2012

The audit log with reversible operations

Though audit is eventually going to befall the enterprise, rarely do we see any of them take proactive action on the most precious of data: the identity store. It is a sad realization, if a matter-of-factly one, especially when you know there some neat features in the UnboundID product line squarely aimed at making auditing easier but a valuable risk hedging practice to deploy across the board. Here is the first step you can take to wrap your head around it:
  a) enable an audit log publisher, just so you can see what goes in the log
dsconfig create-log-publisher --publisher-name "File Based Audit Log" --type file-based-audit --set enabled:true --set suppress-internal-operations:true --set log-file:logs/audit --set "rotation-policy:24 Hours Time Limit Rotation Policy" --set "retention-policy:File Count Retention Policy" --set include-requester-ip-address:true --set use-reversible-form:true
  You can obviously also go do this on the web console or the dsconfig interactive cli. This just makes it an easy copy/paste.


   b) fire some operations
  we'll simply create an object here and delete it immediately afterwards, just so we get something in the new log...

# bin/ldapmodify -a -c


Arguments from tool properties file:  --hostname localhost --port 9389
--bindDN o=i --bindPasswordFile config/i.pwd


dn: cn=test.0,o=demo
objectclass: person
cn: test.0
sn: demo


# Processing ADD request for cn=test.0,o=demo
# ADD operation successful for DN cn=test.0,o=demo


# bin/ldapdelete cn=test.0,o=demo




Arguments from tool properties file:  --hostname localhost --port 9389


--bindDN o=i --bindPasswordFile config/i.pwd

Processing DELETE request for cn=test.0,o=demo
DELETE operation successful for DN cn=test.0,o=demo

  c) check out the audit log
# 21/Jan/2012:15:46:15.617 -0600; conn=10; op=1; clientIP=127.0.0.1
dn: cn=test.0,o=demo
changetype: add
objectClass: person
objectClass: top
cn: test.0
sn: demo
ds-entry-unique-id:: IAa+rBsFTZi3P6lpUaFG3Q==
ds-update-time:: AAABNQI76kc=
ds-create-time:: AAABNQI76kc=
creatorsName: cn=Directory Manager,cn=Root DNs,cn=config
modifiersName: cn=Directory Manager,cn=Root DNs,cn=config


# 21/Jan/2012:15:48:03.092 -0600; conn=13; op=1; clientIP=127.0.0.1
# Deleted entry attributes
# dn: cn=test.0,o=demo
# objectClass: top
# objectClass: person
# cn: test.0
# sn: demo
# ds-entry-unique-id:: IAa+rBsFTZi3P6lpUaFG3Q==
# ds-update-time:: AAABNQI76kc=
# ds-create-time:: AAABNQI76kc=
# creatorsName: cn=Directory Manager,cn=Root DNs,cn=config
# modifiersName: cn=Directory Manager,cn=Root DNs,cn=config
# subschemaSubentry: cn=schema
# entryUUID: 2006beac-1b05-4d98-b73f-a96951a146dd
# createTimestamp: 20120121214615.495Z
# modifyTimestamp: 20120121214615.495Z
# ds-entry-checksum: 3969919676
dn: cn=test.0,o=demo
changetype: delete

OK so what do we have here? Both operations are reported with enough information to review at a later time. Note too that the delete operation doesn't merely contain the delete instruction but also the contents of the object being deleted, in the event that this was an operator or application error, you would have a simple way to revert the change and restore the original entry without fear of losing precious information.


I invite you to get more familiar with this type of logger, as it can be tweaked to do a lot more. For example you may restrict the logger to only log traffic satisfying certain criteria on the connection (IP, security and such), the type of request and/or the results being fetched(a certain type of sensitive data, entry, ...).
It's a very powerful framework, give it a whirl some time.

January 26, 2012

Figuring out where the server spends time

The UnboundID products offer unique observability features to help understand how deployments behave and where to improve.
One of them is the sup-operation timer, a facility allowing to peek into processing times for operations of interest.
First, we need to enable it:
$ dsconfig set-global-configuration-prop --set enable-sub-operation-timer:true
$ dsconfig create-log-publisher --publisher-name "Operation Timing Access Log" --type operation-timing-access --set enabled:true --set log-file:logs/operation-timing --set "rotation-policy:24 Hours Time Limit Rotation Policy" --set "retention-policy:File Count Retention Policy"


Then we'll search the database so we have something to look at

# bin/ldapsearch -b o=demo "(uid=user.0)"
/usr/bin/tput: unknown terminal "xterm-256color"
/usr/bin/tput: unknown terminal "xterm-256color"


Arguments from tool properties file:  --hostname localhost --port 9389
--bindDN o=i --bindPasswordFile config/i.pwd


dn: uid=user.0,ou=People,o=demo
objectClass: top
objectClass: person
objectClass: organizationalPerson
objectClass: inetOrgPerson
postalAddress: Aaren Atp$01251 Chestnut Street$Panama City, DE  50369
postalCode: 50369
description: This is the description for Aaren Atp.
uid: user.0
userPassword: {SSHA}Xbl7h2+tKwok2OQ2CsPcI1QmWpdZfyHkvGp+Ng==
employeeNumber: 0
initials: ASA
givenName: Aaren
pager: +1 779 041 6341
mobile: +1 010 154 3228
cn: Aaren Atp
sn: Atp
telephoneNumber: +1 685 622 6202
street: 01251 Chestnut Street
homePhone: +1 225 216 5900
l: Panama City
mail: user.0@maildomain.net
st: DE


Finally, we can look at how this operation was processed and where the server spent the time. It is important to note that the times here are in microseconds except for "etime" (in milliseconds), the decimals would therefore be nanoseconds, providing the most fine-grained information on processing time we can to help you figure out where you will get the most bang for the buck trying to optimize your service. Let's have a look:


# vi logs/operation-timing 

[21/Jan/2012:14:56:17 -0600] SEARCH RESULT conn=7 op=111665 msgID=111666 base="o=demo" scope=2 filter="(uid=user.1)" attrs="ALL" resultCode=0 etime=0.038 entriesReturned=1 mostExpensivePhase="SENDING_RESULT" mostExpensivePhaseTimeMicros=19.030 mostExpensiveAggregatePhase="SENDING_RESULT" mostExpensiveAggregatePhaseTimeMicros=19.030 phaseTimesMicros="CREATING_OPERATION=1.434 ENQUEUEING=2.815 RUNNING=0.452 INVOKING_PRE_PARSE_PLUGINS=0.069 PARSING_OPERATION_WIDE_REQUEST_CONTROLS=0.242 LOGGING_REQUEST=0.259 WAITING_ON_THREAD=2.297 CHECKING_CLIENT_CONNECTION_POLICY=0.289 SELECTING_SUBTREE_VIEW=1.800 CREATING_WRAPPED_OPERATION=0.092 ATTACHING_BACKEND_OPERATION=0.380 BEGINNING_PROCESS_OPERATION=0.090 HANDLING_TRANSACTION_CONTROL=1.225 HANDLING_REQUEST_CONTROLS=0.050 CHECKING_ACL_OPERATION_ALLOWED=0.266 INVOKING_PRE_OPERATION_PLUGINS=0.084 INVOKING_BACKEND_PROCESSING=0.285 JE_BACKEND_ENTRY_CONTAINER_SEARCH=0.617 JE_BACKEND_ATTRIBUTE_INDEX_EVALUATE_EQUALITY_FILTER=0.422 JE_BACKEND_INDEX_READ_KEY=0.113 JE_BACKEND_DB_READ=5.109 JE_BACKEND_ENTRY_CONTAINER_SEARCH_INDEXED=0.322 JE_BACKEND_ID2ENTRY_GET=0.102 JE_BACKEND_DB_READ=2.549 JE_BACKEND_ID2ENTRY_DECODE=13.422 BEGINNING_RETURN_ENTRY=0.202 CHECKING_ACL_ENTRY_ALLOWED=0.707 PREPARING_ENTRY_FOR_RETURN=4.006 CHECKING_ACL_FILTER_ATTRIBUTES=0.361 INVOKING_SEARCH_ENTRY_PLUGINS=0.083 SENDING_SEARCH_ENTRY=2.014 LOGGING_SEARCH_ENTRY=0.358 INVOKING_POST_OPERATION_PLUGINS=0.228 SETTING_PROCESSING_STOP_TIME=0.098 SENDING_RESULT=19.030"


Some subtitles may help, so let's look at a few things:
etime -highlighted in blue- stands for elapsed time. It totals at 38 microseconds here.
That is the total time between the server being handed the tcp packet(s) by the operating system, processing the request and returning a response. So it is the server-side perception of the elapsed time.


 As you can see, the most time consuming phase in the processing of this operation was actually putting the result back on the wire to get the result back to the client. It may seem like a small number but if you put that in perspective, since the entire processing time was 38 microseconds, spending 19 to send the result to the client means we are effectively spending 50% of the time waiting for I/O, which is indeed quite enormous.


So that is all, just one more thing to help get to the bottom  of performance optimizations...

January 24, 2012

using tools properties for easy day-to-day operations

You can use the tools.properties file in the /config directory for either OpenDS, OpenDJ or any UnboundID product (DS, Proxy or Sync) to make your life tremendously easier when dealing with your regular instance.
Here's how, simply enter your regular parameters like so:



dsconfig.hostname=localhost
dsconfig.port=9389
dsconfig.bindPasswordFile=config/i.pwd
dsconfig.bindDN=o=i
dsconfig.useNoSecurity=true

then invoking dsconfig will be as easy as just typing the command, all the parameters will be automatically picked up from the properties file:

# bin/dsconfig
Arguments from tool properties file:  --useNoSecurity true --hostname
localhost --port 9389 --bindDN o=i --bindPasswordFile config/i.pwd






>>>> UnboundID Directory Server configuration console main menu


What do you want to configure?


    1)  Backend               7)   Log Retention Policy
    2)  Connection Handler    8)   Log Rotation Policy
    3)  Global Configuration  9)   Password Generator
    4)  Local DB Index        10)  Password Policy
    5)  Location              11)  Password Validator
    6)  Log Publisher         12)  Work Queue


    o)  'Basic' objects are shown - change this
    q)  quit


Enter choice: 


Voilà.

January 23, 2012

2 JeeNodes go to a bar ...

Well, we are 1/12th into 2012 now and I have been dutifully implementing JCW recommendation for the new year of wisely using my 5,000 waking hours and I am happy to report that I have had my setup controlling my HVAC and reporting the temperatures on pachube (I even fixed some bugs in the jPachube library while I was at it, open source fun) for 5 months now, despite some initial skepticism from some members of the Jee community which I am happy to be part of, however small my participation and time allotment to it is.

The funny part is there have been some glitches, one of them was that the JeeLink totally disappeared from Linux, like the USB port had nothing plugged in it. But that is the beauty of internet, I was able to fix everything remotely after that...

anyway, I also have been working on a very simple little GWT application to make a very nice, though simple, UI for the off-the-shelf sketch loaded on the JeeNodes to allow anyone to use them with point and click ease. I will share after having -slowly, mind you- spent time on it to make it shareable.
onwards!  

January 21, 2012

Installing a modern DS in one fell swoop

for quick demo purpose ...
  a) installs and starts the UnboundID server with a 4g heap, startTLS and SSL enabled serving a self-signed cert.

$./setup --cli --no-prompt --acceptLicense --ldapPort 9389 --ldapsPort 9636 --generateSelfSignedCertificate --enableStartTLS --baseDN o=demo --sampleData 9 --aggressiveJVMTuning --maxHeapSize 4g --rootUserDN o=i --rootUserPassword p

UnboundID Directory Server 3.2.0.6
Please wait while the setup program initializes...
Configuring Directory Server ..... Done
Configuring Certificates ..... Done
Importing Automatically-Generated Data (9 Entries) ....... Done
Starting Directory Server ........ Done


Warning: the collect-support-data tool is used to collect information about
your system for support purposes.  The following commands invoked by this tool
were not found in the system path.  You should consider installing them in the
event that you need support for this system:  patchadd


To see basic server configuration status and configuration you can launch
/ds/arno/UnboundID-DS/bin/status


See /ds/arno/UnboundID-DS/logs/tools/setup.log for a detailed log of this
operation.
$

  b) installs and starts the either the Oracle or ForgeRock server, startTLS and SSL enabled serving a del-signed cert.
   b-1) ForgeRock:
$ ./setup --cli --no-prompt --ldapPort 9389 --ldapsPort 9636 --generateSelfSignedCertificate --enableStartTLS --baseDN o=demo --sampleData 9  --rootUserDN o=i --rootUserPassword p


OpenDJ 2.4.4
Please wait while the setup program initializes...


See /var/folders/f5/5bftn0fs2_7_8ct2bqf58h0h0000gn/T/opends-setup-3213346674147849266.log for a detailed log of this operation.


Configuring Directory Server ..... Done.
Configuring Certificates ..... Done.
Importing Automatically-Generated Data (9 Entries) ....... Done.
Starting Directory Server ....... Done.


To see basic server configuration status and configuration you can launch /Users/arno/Downloads/OpenDJ-2.4.4/bin/status
$
    b-2)Oracle:

./setup --cli --no-prompt --ldapPort 9389 --ldapsPort 9636 --generateSelfSignedCertificate --enableStartTLS --baseDN o=demo --sampleData 9  --rootUserDN o=i --rootUserPassword p

OpenDS Directory Server 2.2.1
Please wait while the setup program initializes...

Configuring Directory Server ..... Done.
Configuring Certificates ..... Done.
Importing Automatically-Generated Data (9 Entries) ....... Done.
Starting Directory Server ....... Done.

See /var/folders/f5/5bftn0fs2_7_8ct2bqf58h0h0000gn/T/opends-setup-153139788483549661.log for a detailed log of this operation.

To see basic server configuration status and configuration you can launch /Users/arno/Downloads/OpenDS-2.2.1/bin/status