HFM Data Audit (part 2)

In the previous post I detailed the mechanics of enabling and exporting data audits in HFM.  But what can you do with data once it's exported?

One option is to keep those .csv files for an arbitrary period of time.  If an issue arises you could search all those files for data of interest.  But you need some utility to search many files for text of interest and you could run into space issues which would require deleting deleting old data.

I prefer to import the data into a SQL database.  The data can be kept as long as needed and is easier to search.

With SQL server we can use the bcp utility to import the .csv files into a database table.  The table should match the fields we get in the .csv file.  The following is a sample create table statement to match the .csv file format.

CREATE TABLE [dbo].[AuditRecords](
[UserName]   [nvarchar](32) NULL,
[Activity]   [nvarchar](16) NULL,
[Timestamp]  [datetime] NULL,
[ServerName] [nvarchar](8) NULL,
[Scenario]   [nvarchar](16) NULL,
[Year]       [smallint] NULL,
[Period]     [nvarchar](3)  NULL,
[Entity]     [nvarchar](32) NULL,
[Value]      [nvarchar](16) NULL,
[Account]    [nvarchar](40) NULL,
[ICP]        [nvarchar](24) NULL,
[Custom1]    [nvarchar](32) NULL,
[Custom2]    [nvarchar](24) NULL,
[Custom3]    [nvarchar](8)  NULL,
[Custom4]    [nvarchar](32) NULL,
[DataValue]  [nvarchar](24) NULL
)

Now that we have a table to hold our data we need to import it.  The bcp utility uses an import format file to specify how to parse fields in the file being imported.  The specifications for the format file are kind of klunky which you can read about here.  But this is the format file I use:

10.0
16
1   SQLCHAR   0   64      ";"      1     UserName           SQL_Latin1_General_CP1_CI_AS
2   SQLCHAR   0   32      ";"      2     Activity           SQL_Latin1_General_CP1_CI_AS
3   SQLCHAR   0   24      ";"      3     Timestamp          ""
4   SQLCHAR   0   16      ";"      4     ServerName         SQL_Latin1_General_CP1_CI_AS
5   SQLCHAR   0   32      ";"      5     Scenario           SQL_Latin1_General_CP1_CI_AS
6   SQLCHAR   0   7       ";"      6     Year               ""
7   SQLCHAR   0   6       ";"      7     Period             SQL_Latin1_General_CP1_CI_AS
8   SQLCHAR   0   64      ";"      9     Entity             SQL_Latin1_General_CP1_CI_AS
9   SQLCHAR   0   32      ";"      10    Value              SQL_Latin1_General_CP1_CI_AS
10  SQLCHAR   0   80      ";"      11    Account            SQL_Latin1_General_CP1_CI_AS
11  SQLCHAR   0   48      ";"      12    ICP                SQL_Latin1_General_CP1_CI_AS
12  SQLCHAR   0   64      ";"      13    Custom1            SQL_Latin1_General_CP1_CI_AS
13  SQLCHAR   0   48      ";"      14    Custom2            SQL_Latin1_General_CP1_CI_AS
14  SQLCHAR   0   16      ";"      15    Custom3            SQL_Latin1_General_CP1_CI_AS
15  SQLCHAR   0   64      ";"      16    Custom4            SQL_Latin1_General_CP1_CI_AS
16  SQLCHAR   0   48      "\r\n"   17    DataValue          SQL_Latin1_General_CP1_CI_AS

Now we have a place to store our audit data and a way to import it.  The last step is to automate the whole process.  I run a PowerShell script daily that uses the AuditExport_cmd.exe to export yesterday's audit data to a .csv, and then import it into the database.  I also retain the .csv files in case something goes haywire with the bcp import.  I organize these retention folders by month and year in a parent folder named D:\LogArchives and periodically purge old retention folders.

The files created by the AuditExport utility have a maximum size of 17 Mb which may create more than one file per export.  The script needs the ability to import multiple files in a single batch.  The full script will export the data to a holding area, create a folder for retention if needed, then loop through the files in the holding area, import each with bcp into the database, then move file to the retaining folder.

One issue I ran into is that the data exported is in unicode format but bcp requires ASCII.  Also bcp runs on the SQL server.  I resolved this by importing the .csv file using Get-Content then exporting it using Out-File with the ASCII -encoding switch.  Since I have to run bcp on the SQL server the Out-File target is a share on the SQL server.  That share also has the bcp format file and a batch file to run the import.  This resolves the file format issue and keeps everything tidy on the SQL server.

The batch file on the SQL server is:

bcp DataAuditArchive.dbo.AuditRecords in T:\DataAudit\TempDataAudit.csv -U DataAudit_update -P Password123 -F 2 -f T:\DataAudit\DataAudit.fmt -e T:\DataAudit\DataAudit.err

Here my database is named DataAuditArchive and the table is AuditRecords.  The batch file, bcp format file, error file, and temporary copy of the .csv being imported are all in the T:\DataAudit folder.  This one line batch file gets called from a PowerShell script that runs on the HFM server.

I also want to save all of the output in case something goes wrong.  I do this by piping all of the results to a log file that gets saved in the monthly archive folder.  This gives an audit trail for the script file processing to allow troubleshooting.  If I find that one or more of the .csv files did not import I can import those manually from the retaining folder to ensure a complete audit record.

In the PowerShell script below the $Folder variable holds the name of the current months retaining folder which will house all of the .csv files for the month as well as the log file.  The $Working folder houses the initial export from the AuditExport utility.  The $BCPWorking folder is the share on the SQL Server that has the batch file, bcp import format, and the ASCII version of the .csv file currently being processed.

# Powershell script to archive and truncate data audit logs ending yesterday.
#

$Utility = 'D:\Oracle\Middleware\EPMSystem11R1\products\FinancialManagement\Utilities\HFMAuditExtractCmdLine_x64.exe'
$AppName = 'COMMA' # Name of the HFM Application
$Parms = ' -u D:\HFM.udl -a '+$AppName+' '  # UDL file and application name
$Data = ' -r '                              # flag to extract and truncate the data audit logs
#$Data = ' -x '                             # flag to extract and truncate the data audit logs
$Logs = 'D:\LogArchives\'                   # Parent folder for the log files
$TempFolder = 'Daily' # Store the dump from the HFMAuditExtract utility here
$BcpWorking = '\\SqlSvr\DataAudit'          # local folder on SQL server for BCP to use for import
$Start = ' -s 1/1/2013'                     # Arbitrary start date to make sure we get all previous data

$D = get-date

# New folder for each month that is named with the year and month
#
$Folder = $D.ToString('yyyy')+"_"+$D.ToString('MM')+$D.ToString('MMM')

# Capture everything through yesterday
#
$D = $D.AddDays(-1)
$End = ' -e '+$D.ToString('MM')+'/'+$D.ToString('dd')+'/'+$D.ToString('yyyy')

$Target = $Logs+$Folder                              # Destination for the logs
if (-not (test-path $Target)) { MkDir $Target }      # Create the destination folder if needed
$Working = $Logs+$TempFolder
$Output = ' -d '+$Working                            # Add the -d so this can be used as a parameter for the utility.

# Extract and truncate the task log
#   NOTE: the truncate task for data also does an extract
#
$CMD=$Utility+$Output+$Start+$End+$Parms+$Data       # Create the string to execute.  Path of utility and all parameters
echo $CMD                                            # Echo so we know what we did
invoke-expression $CMD                               # Execute the AuditExtract command line

# Process the file(s) that were created in the TempFolder
#
$TempFile = $BCPWorking + "\TempDataAudit_$AppName.csv"
$ScriptLog = $Target + '\BcpImport.log'
$BatchName = "T:\DataAudit\Import$AppName.cmd"

$AuditLogs = get-childitem $Working -filter "Data*$AppName*.csv"
foreach ($Log in $AuditLogs) {
    echo $Log.FullName

# Export the file be ANSI encoding because bcp has trouble with format files and unicode data files
#
    get-content $Log.FullName | out-file $TempFile -encoding ASCII

#   Run bcp to import the data
#
  $BcpResults = invoke-command -computername SqlSrv -scriptblock { Param($Bat) & cmd.exe /C $Bat } -ArgumentList $BatchName

# Move the file dated archive folder
#
  $MoveResults = Move-Item $Log.FullName $Target -passthru

# Delete the ASCII file we just imported
#
  if (test-path $TempFile) { del $TempFile }

# And save the results to the script log
#
  (' * * * ') | out-file $ScriptLog -append
  $Log.FullName | out-file $ScriptLog -append
  (' ') | out-file $ScriptLog -append
  $BcpResults | out-file $ScriptLog -append
  (' ') | out-file $ScriptLog -append
  $MoveResults | out-file $ScriptLog -append
}

This script is scheduled to run daily which keeps the DataAudit table in the HFM database lean and efficient.  The audit table becomes our source of truth unless the event happened today in which case we use the Data Audit tab in Workspace.

HFM Data Audit (part 1)

Don't you hate it when you're watching a TV show and it builds to a crecendo only to leave you with a "To be continued..." screen at the end.  You invest all that time just to get teased into watching next week.  I'm letting you know up front I'm not covering everything I intend to show about HFM data auditing.  This post will deal with the mechanics of configuring and exporting the data audits.  The next post will address what we can do with the exports to make them useful for reference.

We used to get reports from users in the field that somebody moved their cheese.  Fingers were pointed, accusations made, email storms erupted, tsunamis demolished fragile shore lines, meteors collided in the stratosphere, all cascading into a cacophony of dissonance that gradually decrecendoed until the next crisis wherein the entire process repeated.  The decision was made to enable data auditing in HFM to prevent such catastrophes.

The good thing about data auditing in HFM is that it records every transaction including data entry, data loads, data clears and data copies.  The bad thing about data auditing in HFM is that it records every transaction, so unless you are surgical about what gets audited you can generate an enormous log.

Data auditing is configured at the intersection Scenario and Account.  For Scenarios the field Enable Data Audit has to be set to Y (yes) or O (override) instead of the default of N.  Y indicates that everything in that scenario gets audited, O indicates the auditing is optional and will defer to the configuration of the Account dimension.  Unless you have a small Account dimension you should configure the audited scenarios with the O.  Only audit scenarios where users make changes.

For the Accounts dimension change the Enable Data Audit field to Y for the accounts to be audited in Scenarios configured with O.  Again, only audit accounts where users make changes.  There is no value to auditing accounts that are calculated.  FDQM it has its own audit trail so if you use that to load data you should try to omit accounts that FDQM loads and just audit accounts where users manually submit or clear data.  In our case we knew there were specific areas that generated problems so we focused on accounts in those areas.

The audit data can be viewed in workspace by selecting Navigate > Administer > Consolidation Administration > Audit > Data Audit.  The resulting data can be filtered by any of the POV fields.  The data grid will show who did it, what they did, when they did it, where they did it, the POV of the intersection touched, and the value assigned.

The data audit details are in the table <AppName>_DataAudit.  The HFM administrators guide advises that the number of records in the table be less than 500,000 to avoid degrading performance.  For a large company half a million records can be added in an afternoon of data loads during month end close.

The audit data can be exported and truncated from the Consolidation Administration tab.  But a better solution is to find an automated way of exporting and truncating the table.  In the EPMSystem11R1\products\FinancialManagement\Utilities folder is the command line utility HFMAuditExtractCmdLine.exe.  This utility has switches to truncate and/or extract the data and task audit logs for a consolidation application.  Data can be extracted or truncated within a specified date range and extracted to any available location.  Note that the utility requires a Universal Data Link (.udl) file which must be configured with the connection string to the HFM database along with credentials that have at least db_datawriter access to the database.

The command line to extract the data is pretty straightforward.  Assign the destination folder, full path to the .udl file, specify the application, delimiter, start, and end dates, and the switches for which operations to perform.  One quirk I found, at least with the 64-bit version of the utility for 11.1.2.2.500, is that -k and -r switches both export and truncate the data instead of just truncating.

HFMAuditExtractCmdLine_x64 -d c:\Extracts -u C:\MyHFM.udl -a Comma -s 2017/01/01 -e 2017/02/29 -r

This example command will extract the data to the C:\Extracts folder, use the C:\MyHFM.udl file to connect to the HFM database and the Comma application, then extract and truncate all of the data audit records recorded between January an February of 2017.  Note that in the example I'm using the default delimiter which is the semicolon.  If you specify a delimiter it must be a printable character since there is a known issue with the command line utility which can't process [Tab] as a delimiter.

The command line utility is available up to version 11.1.2.3, but is not bundled with version 11.1.2.4 and above.  However the format of the table has not changed between versions so the utility will still work.  Oracle patch 9976978 can be downloaded to get an older version of the utility.  You can also get the latest PSU for a previous version which will have a copy of the utility in the files\products\FinancialManagement\Utilities folder.

The utility can be configured in a batch file or run directly from the Task Scheduler.  But we still need to adjust the end date.  In the next post I will detail sample code that exports the data to a .csv file, adjusting for the date, and imports that .csv file into a database.  I use this as a nightly scheduled process to keep the HFM database lean and preserve the audit data for forensic examination.

Auditing Financial Reports

You know how it goes.  Somebody starts a project and then forgets about it.  Or there are multiple versions of a report that were made for various purposes.  Or a report was critical at one point but eventually interest waned and is now unused.  Whatever the cause you wind up with a bunch of reports, books, and batches that are never used.  But you can't tell which ones aren't used if you don't have an audit trail.

There other uses for an audit trail beyond finding which reports are used.  Maybe you need to know who runs the reports, or how frequently reports are generated, or if reports are run at a certain times so you can plan maintenance.  Or maybe you're just curious.

Oracle docs 1353965.1 and 1947774.1 show the FRLogging.log file holds the audit data of Financial Reporting objects.  The FRLogging.log contains a bunch of information including start and stop times for reports and books, steps taken to produce output, queries used to pull from the data source, and other details.

The Problem

As noted in the 1947774.1 document you configure logging in the  MIDDLEWARE_HOME/user_projects/domains/EPM_System/config/fmwconfig/servers/FinancialReporting0/logging.xml file.  By default BI+ limits the log file size to 1Mb.  When the log reaches that limit the FRLogging.log file is renamed by appending a sequential number to the file name and a new log file is created.  By default only 50Mb of log files are retained.

This is good news because BI+ won't create an infinite number of logs which could fill your drive and crash your system.  But this is bad news because you can blow through 50Mb of logging in an afternoon of running multiple report batches during month end close, thus losing historical data.

Also the logs contain a lot of information that isn't interesting from an audit stand point.  We just want lines that show the name of the report as well as the time it ran and the user who ran it.

We have to parse the FRLogging logs to get just the summary information.  But we can't process the FRLogging.log file directly because it is held open by the Financial Reporting services and new records are constantly being appended.

The Solution

Windows has a .NET class called FileSystemWatcher.  This will monitor a file or folder and take action when file system events occur such as creating, deleting, or renaming a file.  We can use this feature to monitor the FRLogging.log file.  When it gets renamed we find the newest numbered file in the folder and process that.  This allows us to process a file that is not in use and prevents us from processing a log file more than once.

There are several lines in the FRLogging.log that are useful for audits.  The START: record gets added when the job starts and the JOB: record gives a completion summary of the job including the total time it took the job to complete.  In between these are one or more REPORT: records.  If you run just the report you get one REPORT: record but for a book or batch you will get multiple records, one for each report generated.

Each of those lines contain the string "start:" (note the colon in the string).  For the JOB: and REPORT: records this string identifies the start time of the event while for the START: records the string is the record identifier.  No other records contain this string so this is a sure way to parse the log for the audit data.

To put this all together we need a script that will run FileSystemWatcher, wait for the FRLogging.log file to get renamed, find the latest numbered file, do a case-insensitive search for lines with the string "start:", and drop those lines into a file we can retain for as long as we need.  This PowerShell script accomplishes those tasks:

# PoSh script to keep a record of all report usage
#   Use the FileSystemWatcher to monitor the FRLogging.log.  When the file gets renamed
#  we pull the job information from the most recent file and save it to an audit log
#
$Folder = `
"D:\Oracle\Middleware\user_projects\domains\EPMSystem\servers\FinancialReporting0\logs"
$File   = "FRLogging.log" # File to monitor with FileSystemWatcher
$Filter = "FRLogging*.log" # Filter to find the most recently renamed file
$Output = "D:\FRAudit.log" # Running audit trail

# Configure the FileSystemWatcher.  Create the watcher object, then define the
# folder and file to watch
#
$watcher        = New-Object System.IO.FileSystemWatcher
$watcher.Path   = $Folder
$watcher.Filter = $File

# Define the action to take when the file we are watching gets renamed
#
$renamed = Register-ObjectEvent $watcher "Renamed" -Action {

  # Get the FullName of the most recent numbered FRLogging*.log file
  $LogFile = (Get-ChildItem $Folder $Filter | Sort LastWriteTime -desc)[1].FullName

  # Do a case insensitive search for all lines that contain the string "start:"
  $NewRecs = get-content $LogFile | where {$_ -match "start:"}

  # And append those lines to our running audit trail
  $NewRecs | out-file $Output -append
}

If you use this script you will need to change the value for the $Folder variable to match your environment.  The value of the $Output variable is arbitrary but must be the full path to a file for your running audit trail.  The tricky part of the script is the line where we find the most recent log file.  Get-ChildItem returns an array of files matching the filter in the folder.  We sort that array by LastWriteTime in reverse order and take the second element of the array (index [1]) to get the latest numbered file since the first element (array index [0]) is the FRLogging.log file.

But how do we make sure the script stays running to continuously monitor the FRLogging.log file?

An easy solution is to use Windows Task Scheduler to create a task that runs at system startup.  You can also start the task manually when you first create it or if you adjust it later.  Since there is nothing to terminate the script the task keeps running in the background.  We basically get a service that starts automatically at every reboot.

Our new audit log is just a raw dump of the the useful lines from the FRLogging.log file.  You will still need to parse that data to isolate the information of interest to you.  (I have another PowerShell script to do that and will send it to you if you are interested.)  But the key point is that we can leverage the transient information Oracle gives us and generate a persistent audit trail.  And we can do it for free using built-in tools and with minimal overhead.