Troubleshooting HFM 11.1.2.4 on Windows

HFM on 11.1.2.4 and higher versions has a significantly different architecture than previous versions. This difference makes troubleshooting issues much harder. The old tricks seem out of date and it is easy to feel lost in the new version. Unfortunately, getting lost and unable to solve problems can lead to downtime and project delays. I wanted to share some basic tips to help get started in 11.1.2.4. Specifically, I wanted to focus on Windows because I have covered Linux in previous posts.

First, let's take a real error while creating a brand new HFM application.

Here we get the error: EPMHFM-66054: The system was unable to find the Datasource process for application. Essentially each HFM application spawns its own process in HFM and this application crashed while trying to initialize. This could be due to any number of things...

The first thing to note is the old HFMErrorLogViewer from previous versions is gone. The HFMErrorLogViewer was a great tool because it collected all the backend log messages into one convenient place. Now it looks like things are spread out over many logs. 

First, HFM is broken down at a high level into the Weblogic/ADF components and the Java HFM Wrapper Engine. They appear as Windows services,

The Web Tier consists of the Weblogic applications & UI. These logs can be found under the WebLogic domain,

The Java Server is the more interesting of the two for debugging because most significant errors can be traced to the backend. One thing to realize is HFM is still only partially Java based. There are still significant portions of HFM representing legacy code written in C. These low level functions are wrapped into this Java framework to make it look seamless. 

Let's take a look at some of the backend logs.

One of the main logs to investigate is under 

Oracle\Middleware\user_projects\epmsystem1\diagnostics\logs\hfm

The hsx-server log will have most details regarding the HFM backend service, similiar to the messages you would see previously in the HFMErrorLogViewer.

oracle-epm-fm-hsx-server.log

startDatasourceProcess] Starting a new datasource process for the application TESTHFM999[2016-04-23T00:29:43.500-07:00] [FM] [NOTIFICATION] [] [oracle.FM.HSXDSLM.oracle.epm.fm.dslm.DatasourceProcessManager] [tid: 12] [ecid: 005CI7TJTRS8dplqwsedMG0006Vu001PXQ,0:1:4] [SRC_CLASS: oracle.epm.fm.dslm.DatasourceProcessManager] [SRC_METHOD: getDSCommandLineArguments]  Starting the application TESTHFM999 on the ports : DSManagementPort port 10001 and DSHandler Port 10002
[2016-04-23T00:29:43.532-07:00] [FM] [NOTIFICATION] [] [oracle.FM.HSXDSLM.oracle.epm.fm.dslm.DatasourceProcessManager] [tid: 12] [ecid: 005CI7TJTRS8dplqwsedMG0006Vu001PXQ,0:1:4] [SRC_CLASS: oracle.epm.fm.dslm.DatasourceProcessManager] [SRC_METHOD: isSingleInstance]  Is Single Instance ? true
[2016-04-23T00:29:43.532-07:00] [FM] [ERROR] [EPMHFM-65925] [oracle.FM.HSX.SERVER.oracle.epm.fm.common.HsxServerConfig] [tid: 12] [ecid: 005CI7TJTRS8dplqwsedMG0006Vu001PXQ,0:1:4] [SRC_CLASS: oracle.epm.fm.common.HsxServerConfig] [SRC_METHOD: getDSHangTimeoutPeriod] 

... 

[2016-04-23T00:29:44.485-07:00] [FM] [NOTIFICATION] [] [oracle.FM.HSXDSLM.oracle.epm.fm.dslm.DatasourceProcessManager] [tid: 14] [ecid: 005CI7TJTRS8dplqwsedMG0006Vu001PXQ,0:1:4:21] [SRC_CLASS: oracle.epm.fm.dslm.DatasourceProcessManager] [SRC_METHOD: onProcessFailed] Datasource process for application TESTHFM999 stopped.
[2016-04-23T00:29:44.500-07:00] [FM] [NOTIFICATION] [] [oracle.FM.HSXDATAACCESS.oracle.epm.fm.dal.manager.ApplicationManagerDALImpl] [tid: 14] [ecid: 005CI7TJTRS8dplqwsedMG0006Vu001PXQ,0:1:4:21] [SRC_CLASS: oracle.epm.fm.dal.manager.ApplicationManagerDALImpl] [SRC_METHOD: deleteCCLockRecordsForServer]  Table TESTHFM999_CC_LOCKS does not exist
[2016-04-23T00:29:44.563-07:00] [FM] [WARNING] [] [oracle.FM.HSXDSLM.oracle.epm.fm.dslm.DatasourceManagerImpl] [tid: 12] [ecid: 005CI7TJTRS8dplqwsedMG0006Vu001PXQ,0:1:4] [SRC_CLASS: oracle.epm.fm.dslm.DatasourceManagerImpl] [SRC_METHOD: pingDatasource] Unable to invoke ping on XDS management service for the application TESTHFM999 , 

From this log it is evident that each HFM application creates a new datasource. A datasource is a separate process that handles all the processing for a particular application. The datasource process is launched after creating the application, or on the fly as the application is accessed. 

This spawned datasource process creates a new logfile for each application. For instance, a log file is created with the application name, such as xfm.odl.TESTHFM000-1.log. 

Having a look:

xfm.odl.TESTHFM000-1.log

[2016-04-23T00:29:44.453951-07:00] [XFM] [ERROR:1] [EPMHFM-07392] [XFM] [ecid: XDS.0000.0000.0000.0001] [File: XfmODBC.cpp] [Line: 203] [userId: ] [appName: TESTHFM999] [pid: 19988] [tid: 20008] [host: ] [nwaddr: ] [errorCode: 800402B5] [srcException: NotSpec] [errType: 1] [dbUpdate: 2] [11.1.2.4.200.5149] An unknown error occurred in an ODBC object. [[1 record: SQLSTATE = 08001; NATIVE ERROR = -4; MSG = [DataDirect][ODBC Oracle Wire Protocol driver][Oracle]Connection Dead. This may have occurred because the server requires Oracle Advanced Security. To enable the driver to use OAS, please use the DataIntegrityLevel and/or EncryptionLevel connect options.]] 

[2016-04-23T00:29:44.453951-07:00] [XFM] [ERROR:1] [EPMHFM-07406] [XFM] [ecid: XDS.0000.0000.0000.0001] [File: XfmODBC.cpp] [Line: 615] [userId: ] [appName: TESTHFM999] [pid: 19988] [tid: 20008] [host: ] [nwaddr: ;] [errorCode: 800402C3] [srcException: XfmExc] [errType: 1] [dbUpdate: 1] [11.1.2.4.200.5149] An error occurred in creating an ODBC connection. [[08001]] 

[2016-04-23T00:29:44.469577-07:00] [XFM] [ERROR:1] [EPMHFM-07406] [XFM] [ecid: XDS.0000.0000.0000.0001] [File: XfmODBC.cpp] [Line: 700] [userId: ] [appName: TESTHFM999] [pid: 19988] [tid: 20008] [host: ] [nwaddr: ] [errorCode: 800402C3] [srcException: XfmExc] [errType: 1] [dbUpdate: 1] [11.1.2.4.200.5149] An error occurred in creating an ODBC connection. [[Failed to create DB connection.]] 

So it looks like ODBC is involved here. Essentially, the underlying database connection in HFM is now ODBC. This was done to support HFM on Linux. The ODBC layer is how Oracle choose to make the code OS agnostic.

The ODBC connection is controlled by the Merant DataDirect 7.1 ODBC Driver. This is similar to how external Essbase database connections were created in the past. Looking at the error message, we are getting Connection Dead. This is actually a common problem with the ODBC DataDirect drivers and encrypted database connections. It is possible to reproduce this outside of HFM by testing the ODBC driver by hand:

Open Microsoft ODBC Manager, and add a connection.

HFM uses the DataDirect 7.1 Oracle Wire Protocol

Entering in the basic database connection details:

The exact error message appears, outside of HFM. 

This error message also happens to indicate where to look to solve the issue. In this case, the Oracle Database Listener connection requires an encrypted connection. Unsecured connections are rejected. So we can simply configure the ODBC connection to use the same encryption as the Oracle Listener.

sqlnet.crypto_checksum_server = REQUIRED
sqlnet.crypto_checksum_types_server = (SHA1)
sqlnet.encryption_types_server = (AES256)

Oracle Database Listener Settings

In the ODBC connection there are Advanced Security parameters which allow us to easily match the listener settings.

This is great. However, now we need to figure out where the ODBC connection is stored in HFM in order to configure these advanced properties.

HFM creates a new datasource in the Oracle client called HFMTNS. This info is entered during config tool, and automatically added to the tnsnames.ora in the HFM Database client folder
D:\Oracle\Middleware\dbclient64\network\admin. The ODBC connection leverages this HFMTNS connection information.

Taking a step back, since all of this is actually wrapped into a Java Server container, one additional place for logs is the Windows service start log:

D:\Oracle\Middleware\user_projects\epmsystem1\diagnostics\logs\services

HyS9FinancialManagementJavaServer-sysout.log

Here there is some very interesting information about how this ODBC connection is stored.

[2016-04-23T10:29:07.179806-07:00] XDS: XFMDataSource process starting...[2016-04-23T10:29:07.179806-07:00] XDS: Processing command line arguments...[2016-04-23T10:29:07.179806-07:00] XDS: Initializing XfmJHsxServerWrapper...[2016-04-23T10:29:07.179806-07:00] XDS: Getting database settings from HIT registry ...[2016-04-23T10:29:07.257929-07:00] XDS: Transforming DB connect info from JHsxServer into a DB connect string[2016-04-23T10:29:07.257929-07:00] Connection string: DRIVER={DataDirect 7.1 Oracle Wire Protocol};SRVR=HFMTNS;UID=...;PWD=**********;ENS=1;AN=HFM[2016-04-23T10:29:07.257929-07:00] XDS: Initializing static parameters...[2016-04-23T10:29:07.257929-07:00] XDS: Initializing critical errors log...[2016-04-23T10:29:07.257929-07:00] XDS: Critical errors log: D:\Oracle\Middleware\user_projects\epmsystem1\diagnostics\logs\hfm\TEST23.oracle_critical_errors.log[2016-04-23T10:29:07.257929-07:00] XDS: Initializing ODL logging...Found trace level'TRACE:32' in the logger node[2016-04-23T10:29:07.367305-07:00] XDS: Initializing DB logging...[2016-04-23T10:29:07.820454-07:00] XDS: Failed to run XFMDataSource. Unexpected error occured ...[2016-04-23T10:29:07.836077-07:00] XDS: Right before exit

From the log message it looks like the ODBC connection is created on the fly by transforming the database connection information used by the Java HFM Service, JHsxServer. This comes from the database credentials used when running the HFM config tool during configuration. I find this design unfortunate because there are going to be slight differences between how Java drivers and the DataDirect drivers work for non trivial connections. Looking at the Config Tool advanced properties, there are options for SSL database connections, but all are focused on JDBC (Java) connectivity.

In this case, we see that the DataDirect based encryption properties cannot be set. Since there does not seem to be any way to change the advanced properties, The investigation has hit a dead end and Oracle SR needs created to get this fixed.