Truncating the Job Console logs

In the last post we talked about how to automate deleting the task flow logs.  Another place where log entries accumulate is the Library Job Console.

The Job Console log is more manageable than the Task Flow log.  In the Job Console tab you can display up to 200 entries per page and you can click the first record, scroll to the bottom of the list, shift+click to select all the entries, then right-click and delete.

This is better but can still be a bunch of work if you haven't cleared the logs in a while.  And wouldn't you rather have an automated solution that can be scheduled so you can work on other things?  Of course you would.

Analysis

The discovery was pretty easy.  In the EPMA database the table name [JM_Job] is a dead give away.  The contents show the same information we see in the Job Console tab.

There are three tables with the JM* prefix which hold the job log data: [JM_Job], [JM_Batch], and [JM_Attachment].  They are connected by the i_job_id key which has sequential values and is the primary key in the [JM_Job] table.  The [JM_Attachment] primary key combines the i_job_id and the i_attachment_id, where i_attachment_id is also a sequential value.  The primary key for the [JM_Batch] database combines the foreign keys i_job_id and i_attachment_id with the field i_batch_id.

The [JM_Job] database has the start and completion times for the various jobs.  So we can reference that to find our cut off date, get the i_job_id for the previous job, and delete from the three tables anything that is less than the cut off i_job_id.

Solution

The wrinkle is that because of foreign key constraints of i_job_id the [JM_Job] database has to be the last one truncated.  And because the i_attachment_id is a foreign key in [JM_Batch] that has to be the first table truncated.

Like with the task flow truncation we can either calculate or specify the cut off date.

DECLARE @CutOff datetime;
SET     @CutOff = DATEADD(M,-4,GetDate());
--DECLARE @CutOff char(10);
--SET     @CutOff = '2016-01-01'

There are several ways to tackle getting the i_job_id for our cut off date.  One approach is to assign the i_job_id to a variable and use that in the DELETE statement:

DECLARE @ID Int;
SET @ID = (SELECT Top 1 i_job_id FROM JM_Job WHERE d_started < @CutOff ORDER by i_job_id DESC)
DELETE FROM JM_Batch WHERE i_job_id <= @ID

But these are fairly small tables so it is easy to use a subselect in the DELETE:

DELETE from JM_Batch
where i_job_id in (
SELECT i_job_id
FROM JM_Job
WHERE d_started < @CutOff)

The last piece is to arrange the DELETEs in the correct order.  The complete TSQL script is:

use EPMA
go

-- Anything prior to cutoff date will be deleted
--   The DateAdd function can change depending on need
--
DECLARE @CutOff datetime;
SET     @CutOff = DATEADD(M,-4,GetDate());
--DECLARE @CutOff char(10);
--SET     @CutOff = '2015-01-01'
PRINT 'Cut off date = '+convert(VarChar(32),@CutOff)

-- Because of the key constraints the deletes need to happen in this order
--   JM_Batch has to be first because it has keys from JM_Attachment and JM_Job
--   JM_Attachment has key for JM_Job so deletes have to happen before
--     JM_Job but after JM_Batch
--   JM_Job has to be last because that has the date field we query against
--
-- For the first 2 deletes we get a list of i_job_id from JM_Job that are older
--   than the cutoff date, and compare the i_job_id in the table to that list
--
DELETE from JM_Batch
where i_job_id in (
SELECT i_job_id
FROM JM_Job
WHERE d_started < @CutOff)

DELETE from JM_Attachment
where i_job_id in (
SELECT i_job_id
FROM JM_Job
WHERE d_started < @CutOff)

DELETE from JM_Job
where d_started < @CutOff

This gives us a tidy bit of code that we can run on a regular basis to truncate the Library Job Console log to purge stale information.

This blog post is a bit short, so here's a picture of a kitty.

Automate Deleting Taskflow Log

We use HFM taskflows.  A lot.  When a taskflow runs it generates log information so you can check on the status of the execution and examine any errors to effect remediation.

But like the EPMA logs, these log entries stay around forever until you delete them.  On the Task Flow Status page you see each task flow status on a line with a check box.  To delete a log entry you click the check box to select the entry and click the Delete button.  Child's play.

Since these are check boxes you would think, as a standard GUI practice, you could check multiple boxes and click the delete button to delete multiple log records.  You would be wrong.  You have to select the log records one at a time to delete them.  Isn't that convenient?

So if you don't constantly do maintenance you wind up with a bunch of useless information in your log viewer.  Searches take longer and if you want to delete entries it takes a lot of time to complete.  What's a mother to do?

Analysis

We use the taskflows to monkey with our HFM applications.  Taskflows are found in the Consolidation Administration tab so you might think the information for taskflows is in the HFM table.  But we can also do EPMA related things like run data synchronizations and redploy applications.  So where do we find the tables that manage the taskflows and logs?  In the Shared Services database, of course.

It took me some digging to figure that out, but the first clue was finding a table named [ces_wf_instances].  SELECTing from that tables shows the field process_name with the names of my taskflows.  Other useful fields include starttime, a datetime field that we will use to find all the old log entries, and workflow_id and taskid which are used as references to other tables.  workflow_id is the taskid with the string "wf-" as a prefix.  workflow_id is also part of the primary key so it is unique across the tables.



The nice thing is that taskid values are always in ascending order.  I don't have any way to prove this but I suspect that taskid is based at least in part the datetime of the activity.  This means that when we process the other tables we can define a cutoff date, find the first taskid in the [ces_wf_instances] for that date, then delete anything that has a taskid less than that.  The not so nice thing is that in all the other tables the taskid field is named task_id.



What other tables will we process?  There are 13 tables with the ces_ prefix but some of them are empty and others are unrelated to logging.  The [ces_tasks] table lists tasks within the taskflow, [ces_messages] contains more detailed messages about the task.  Both tables contain a field named objectvalue which is an image blob.  This is a large hex string that gets processed to show its part of the workflow status.  Both of these tables are referenced by task_id which, like in [ces_wf_instances], is sequential, so we can still use the strategy of deleting records less than the target task_id.



There are also the [ces_participant] and [ces_participant_events] tables which have details on the steps in the taskflow.  Like the [ces_tasks] and [ces_messages] tables these tables have the objectvalue image blob.  The [ces_participant] is referenced by workflow_id which matches the field in the [ces_wf_instances] table.  There is also a field named participant_id which contains the workflow_id, the user, and the name of the step in the taskflow.  This participant_id is a foreign key in the [ces_participant_events] log.  Because there is a foreign key constraint between the tables when we delete records from the [ces_participant] table the records with the matching participant_id in the [ces_participant_events] table also get deleted.

Solution

So now that we know all the players, let's draw up a play to get us to the end zone.  We will build a SQL script that defines our cutoff date, find the last taskid associated with that date, then delete records from the other tables where the taskid is less than the one for the target date.

There are different tactics to define the cut off date.  If we are running this process manually maybe we just want to define the date with a static string:

DECLARE @PriorDate DateTime;
SET     @PriorDate = '2015-01-01';

But if we want to create a scheduled process we can calculate the desired cut off date.  For example, the following code will use the DATEADD() function to set the cut off date as 3 months prior to the current date:

DECLARE @PriorDate DateTime;
SET     @PriorDate = DATEADD(M,-3,GetDate());

Now that we have the date, we need to find the target taskid.  The taskid is sorted sequentially so we take the TOP 1 taskid where the starttime is greater than or equal the cut off date.  Note that we use greater than or equal to (>=) rather than just equal to (=) in case there was no taskflow execution on the cut off date.  This gives us a taskid where anything less will be prior to our cutoff date.  Also note that we make the @LastID variable nvarchar(100) which matches the data type used in the [ces_wf_instances] table.

DECLARE @LastID nvarchar(100);
SET     @LastID = (
  SELECT TOP 1 taskid
FROM [ces_wf_instances]
WHERE starttime >= @PriorDate
)

For the [ces_messages] and [ces_tasks] tables we can do a simple delete where task_id is less than our target taskid.  But for the [ces_participant] table we need to get the workflow_id for all of the records prior to our cut off date.  One way to do this is to use the IN clause and build a list of workflow_id from the [ces_wf_instances] table where the starttime is less than the cut off date.

DELETE FROM [ces_participant]
WHERE workflow_id IN (
select workflow_id
from [ces_wf_instances]
where starttime < @PriorDate)

Remember that because of the foreign key constraint deleting records from [ces_participant] will also delete the associated records from the [ces_participant_events] table.  Also note that because we need the [ces_wf_instances] table to do this delete we have to make that the last table from which we delete records.

The entire SQL script is:

-- Cut off date
DECLARE @PriorDate DateTime;
SET     @PriorDate = DATEADD(M,-3,GetDate());
--SET     @PriorDate = '2015-01-01'
PRINT 'Cut off date = '+convert(VarChar(32),@PriorDate)

-- Get the first datskid of the cutoff date
DECLARE @LastID nvarchar(100);
SET     @LastID = (
select top 1 taskid
from [ces_wf_instances]
where starttime >= @PriorDate
  )
PRINT 'Last TaskID = '+@LastID

-- These tables are simple deletes
DELETE from [ces_messages] where task_id < @LastID
DELETE from [ces_tasks]    where task_id < @LastID

-- [ces_participant] table has a foreign key constraint against [ces_participant_event]
-- table.  Deleting records from [ces_participant] deletes records with the same
-- particpant_id from the [ces_participant_event].  So to process these two tables we
-- get a list of workflow_ids where starttime is less than @PriorDate
DELETE FROM [ces_participant]
WHERE workflow_id IN (
select workflow_id
from [ces_wf_instances]
where starttime < @PriorDate
   )

-- We could also have deleted based on task_id
DELETE FROM [ces_wf_instances]
WHERE starttime < @PriorDate

This gives us a fairly simple SQL script we can schedule as a SQL agent job or any other means appropriate for the environment.  No manual steps, no muss, no fuss, and we keep the taskflow log and the underlying tables lean and manageable.

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.