More Trouble with Temp Files

The title of this post kind of gives away the plot before I even start the story.  But it does give me a chance to use this picture in my blog.

We update our HFM application metadata monthly.  We first deploy the changes in our development environment and test any required changes to member lists, rules, etc.  After the metadata is loaded into EPMA the HFM application has to be redeployed.  In this case the redeploy failed.  The message displayed was almost as useless as a tribble:

The custom error module does not recognize this error.

This is like something you would find on the DailyWTF, an error that tells you nothing more than it's an error.

In the Consolidation Administration tab was an error message that was a little more descriptive, but equally unenlightening.

Could not determine wsdl ports.

Searching the Oracle knowledge base and binggoolging turned up nothing useful.  In cases dealing with workspace we sometimes resolve unusual issues by clearing the browser cache and reopening the browser, but that didn't help.

The deployment failed at 6% which normally indicates a problem with EPMA.  Everything on the EPMA server looked normal and there were no obvious errors in the logs.  We tried restarting just the EPMA services which did not help.  We then restarted all the EPM services to close all connections, flush java caches, and try to clear up whatever was causing the error, but the redeploy still failed at the same step.

Then I checked the HFM server which in our case is a different host than EPMA.  The C: drive was almost full.  Because this is a dev environment I don't have any alerts configured so I didn't have advance warning of the problem.

Analysis

A handy tool for finding disk hogs is the sysinternals du utility.  It runs from the command line but the syntax is easy and you can use keyboard shortcuts to quickly drill down to find the problem folders.

While DU can scan a whole drive and find the hogging subfolders this can take a bit of time.  My strategy is to check just one level use the -L 1 paramenter, then drill down from there one level at a time.  This is usually a quicker way of finding the offending folder.

Here I look in the C:\Users folder because I suspect the problem is one of the profiles.  Clearly the problem is the profile taking over 5Gb with an account that starts with r and ends with v.

Using DOS shortcuts I hit the up arrow key to repeat the last command, add the backslash, type an [r] to start the username, use the [Tab] key to auto-fill the rest of the name, and press [Enter] to see results for the next level down.  Repeat this technique until you find the problem folder.

In this case it was the user profile of the service account that runs the HFM and other EPM servcies.  In the AppData\Local\Temp folder there were a bunch of temp files, many of them tens of megs in size.  After deleting all the temp files from previous years we freed up 5Gb of drive space and the deployment succeeded.

Even though this processing is handled by EPMA, there is still data being written to the HFM server.  Presumably this is so HFM has something to process once its turn in the deployment comes.

Conclusion

This is another episode where temp files don't get cleaned up after execution.  Also note that the .tmp files use the convention of a 4 hex digit as part of the name.  Had we not run out of drive space it is conceivable we would have run into name collision like we did with the Permanent Temporary Files.

This has become another task during the monthly maintenance where logs and other items get purged or truncated to keep the logs manageable and drive space clear.

What is curious in all of this is why aren't these temp files cleaned up as a matter of course?  While it makes sense to keep temp files around for troubleshooting if a process fails, surely whatever process generates these things could have a final step of cleaning up its droppings after it receives a success notice.  Even children know enough to clean up after their dog.

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.