43.1 Using Log Files for Troubleshooting

43.1.1 Customizing Logging Settings

By default, log entries include only function names and not the complete class path that can make it difficult to determine which package is generating a particular message. To include the complete class path in a log message, change all the instances of the following entry in the userapp-log4j.xml file:

<param name="ConversionPattern" value="%d [%p] %c{1} %m%n"/>

to

<param name="ConversionPattern" value="%d [%p] %C %m%n"/>

After making this change, the following example trace entry:

          2017-08-29 16:05:05,392 DEBUG [RBPM] Entity Definition found: sys-nrf-navitem
        

looks similar to this:

2017-08-29 16:05:05,392 DEBUG com.novell.srvprv.impl.vdata.definition.VirtualDataDefinition- [RBPM] Entity Definition found: sys-nrf-navitem

NOTE:The examples in the subsequent sections contain a complete class path to help you correctly interpret the meaning of log entries in the catalina.out file.

43.1.2 Virtual Data Access Logging

The Virtual Data Access (VDA) trace is logged to the catalina.out file when you look for an entity definition.

The VDA issues all of the identity applications LDAP queries for identity data such as entity definition and attributes on the Identity Vault. First it queries the information from the local cache residing on the identity applications server. If the information is not found in the local cache, it queries the Identity Vault. After locating the object, the identity applications read the attributes of the object and map the attributes with the entity definition in the local cache. When the entity definition matches, the identity applications send the data to the client. The trace looks similar to the following:

2017-08-29 16:05:05,389 [http-bio-8443-exec-10] DEBUG com.novell.idm.nrf.util.CacheUtil- [RBPM] Role object was found in cache: cache-key-nrf-config

2017-08-29 16:05:05,389 [http-bio-8443-exec-10] DEBUG com.novell.idm.nrf.util.CacheUtil- [RBPM] Role object RETRIEVED from cache: cache-key-nrf-config

2017-08-29 16:05:05,392 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataAccess- [RBPM] VDA.getEntityResultList

2017-08-29 16:05:05,392 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataModel- [RBPM] VDM.getEntityDefinition(String, Locale):sys-nrf-navitem

2017-08-29 16:05:05,392 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.spi.vdata.util.CacheUtil- [RBPM] DAL Definition is null/not found in cache: VDM_ENTITY_DEFINITION_sys-nrf-navitem, Is object in cache?false

2017-08-29 16:05:05,392 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.definition.VirtualDataDefinition- [RBPM] Entity Definition found: sys-nrf-navitem

2017-08-29 16:05:05,393 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.spi.vdata.util.CacheUtil- [RBPM] DAL definition was found in cache: VDD_ENTITY_ATTR_sys-nrf-navitem

2017-08-29 16:05:05,393 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.spi.vdata.util.CacheUtil- [RBPM] DAL Definition RETRIEVED from cache: VDD_ENTITY_ATTR_sys-nrf-navitem

2017-08-29 16:05:05,393 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.spi.vdata.util.CacheUtil- [RBPM] PUT new DAL Definition into cache: VDM_DEFINITION_ATTRIBUTE_LIST_sys-nrf-navitem

2017-08-29 16:05:05,394 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataModel- [RBPM] VDM.getEntityDefinition(String, Locale):sys-nrf-navitem

2017-08-29 16:05:05,394 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataAccess- [RBPM] VDA.getEntityResultList query filter: (&(objectClass=nrfNavItem))

2017-08-29 16:05:05,439 [http-bio-8443-exec-10] DEBUG com.novell.idm.security.ui.UIProvSecurityUtil- [RBPM] not Admin or Compliance tab, so checkAccess with resource = cn=WorkDashBoard,cn=NavItems,cn=UIConfig,cn=AppConfig,cn=UserApplication,cn=driverset,ou=idm,ou=services,o=system

2017-08-29 16:05:05,443 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataModel- [RBPM] VDM.getEntityDefinition(String, Locale):sys-nrf-user

2017-08-29 16:05:05,444 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.definition.VirtualDataDefinition- [RBPM] Entity Definition found: sys-nrf-user

2017-08-29 16:05:05,444 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.spi.vdata.util.CacheUtil- [RBPM] PUT new DAL Definition into cache: VDM_ENTITY_DEFINITION_sys-nrf-user

2017-08-29 16:05:05,444 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataAccess- [RBPM] VDA.getEntity: cn=mytestuser,dc=data

2017-08-29 16:05:05,444 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.spi.vdata.util.CacheUtil- [RBPM] DAL definition was found in cache: VDD_ENTITY_ATTR_sys-nrf-user

2017-08-29 16:05:05,444 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.spi.vdata.util.CacheUtil- [RBPM] DAL Definition RETRIEVED from cache: VDD_ENTITY_ATTR_sys-nrf-user

2017-08-29 16:05:05,445 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.spi.vdata.util.CacheUtil- [RBPM] PUT new DAL Definition into cache: VDM_DEFINITION_ATTRIBUTE_LIST_sys-nrf-user

2017-08-29 16:05:05,446 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataAccess- [RBPM] VDA.getLdapAttributes Attributes and values

2017-08-29 16:05:05,478 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataAccess- [RBPM] Attribute ID: mail

2017-08-29 16:05:05,478 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataAccess- [RBPM]      mytestuser@acme.com

2017-08-29 16:05:05,478 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataAccess- [RBPM] Attribute ID: modifyTimestamp

2017-08-29 16:05:05,478 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataAccess- [RBPM] 20150716124158Z

2017-08-29 16:05:05,478 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataAccess- [RBPM] Attribute ID: givenName

2017-08-29 16:05:05,478 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataAccess- [RBPM] mytestuser

2017-08-29 16:05:05,478 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataAccess- [RBPM] Attribute ID: objectClass

2017-08-29 16:05:05,478 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataAccess- [RBPM] inetOrgPerson

2017-08-29 16:05:05,478 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataAccess- [RBPM] organizationalPerson

2017-08-29 16:05:05,478 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataAccess- [RBPM] Person

2017-08-29 16:05:05,478 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataAccess- [RBPM] ndsLoginProperties

2017-08-29 16:05:05,478 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataAccess- [RBPM] Top

2017-08-29 16:05:05,478 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataAccess- [RBPM] srvprvEntityAux

2017-08-29 16:05:05,478 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataAccess- [RBPM] Attribute ID: sn

2017-08-29 16:05:05,478 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataAccess- [RBPM] mytestuser

2017-08-29 16:05:05,479 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataAccess- [RBPM] Attribute ID: cn

2017-08-29 16:05:05,479 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataAccess- [RBPM] VDA.checking if object instance contains the required objectClass per DAL definition: sys-nrf-user

2017-08-29 16:05:05,479 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataAccess- [RBPM] VDA.does contain required (search=true or auxilliary=false) objectClass:inetOrgPerson

2017-08-29 16:05:05,479 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataAccess- [RBPM] VDA.object instance is correct type

2017-08-29 16:05:05,479 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataModel- [RBPM] VDM.getEntityDefinition(String, Locale):sys-nrf-user

2017-08-29 16:05:05,479 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.spi.vdata.util.CacheUtil- [RBPM] DAL Definition RETRIEVED from cache: VDM_ENTITY_DEFINITION_sys-nrf-user

2017-08-29 16:05:05,479 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataAccess- [RBPM] VDA.getEntity: cn=mytestuser,dc=data

2017-08-29 16:05:05,480 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.spi.vdata.util.CacheUtil- [RBPM] DAL Definition RETRIEVED from cache: VDM_DEFINITION_ATTRIBUTE_LIST_sys-nrf-user

2017-08-29 16:05:05,481 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataAccess- [RBPM] VDA.getLdapAttributes 
Attributes and values

2017-08-29 16:05:05,481 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataAccess- [RBPM]   Attribute ID: mail

2017-08-29 16:05:05,481 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataAccess- [RBPM]     mytestuser@acme.com

2017-08-29 16:05:05,481 [http-bio-8443-exec-10] DEBUG com.novell.srvprv.impl.vdata.model.VirtualDataAccess- [RBPM] 20150716124158Z

When an entity model is changed, you must clear the VDA cache for the changes to take effect. For example, entity changes occur when a new attributes is added or the existing attributes are modified or removed.

43.1.3 When a Code Map Refresh Is Triggered

When you initiate a code map refresh cycle, sometimes the refresh cycle is not successful. When this occurs, the trace prints messages similar to the following:

2016-11-14 12:28:12,045 [Timer-1] INFO com.novell.idm.nrf.service.CodeMapEngine- [RBPM] Building the Entitlement CODE MAP tables...

2016-11-14 12:28:12,450 [Timer-1] ERROR com.novell.idm.nrf.service.CodeMapEngine- [RBPM] Unable to complete the CODE MAP refresh for entitlement: cn=exchangemailbox,cn=ad,cn=dset,ou=idm,o=system.

2016-11-14 12:28:12,454 [Timer-1] INFO com.novell.idm.nrf.service.CodeMapEngine- [RBPM] CODE MAP refresh on entitlement: cn=exchangemailbox,cn=ad,cn=dset,ou=idm,o=system, processed, next refresh time: 20161115122812-0500.

2016-11-14 12:28:12,646 [Timer-1] ERROR com.novell.idm.nrf.service.CodeMapEngine- [RBPM] Unable to complete the CODE MAP refresh for entitlement: cn=group,cn=ad,cn=dset,ou=idm,o=system.

2016-11-14 12:28:12,835 [Timer-1] ERROR com.novell.idm.nrf.service.CodeMapEngine- [RBPM] Unable to complete the CODE MAP refresh for entitlement: cn=useraccount,cn=ad,cn=dset,ou=idm,o=system.

The first entry indicates that code map table refresh action is being initiated. The second entry specifies that it is unable to refresh the code map table for cn=exchangemailbox,cn=ad,cn=dset,ou=idm,o=system entitlement. The next line has the time interval when the entitlement will be refreshed. The next two lines specify that code map table was not refreshed for cn=group,cn=ad,cn=dset,ou=idm,o=system and cn=useraccount,cn=ad,cn=dset,ou=idm,o=system entitlements.

The code map refresh process can fail when either connected system or the Identity Vault is not up at the time of obtaining entitlement information. The trace logs the actual reason for failure.

43.1.4 When Multiple Users Try to Authenticate From Different Interfaces

OSP supports the OAuth2 specification and requires an LDAP authentication server. By default, Identity Manager uses Identity Vault (eDirectory) as an authentication server. When multiple users try to log in to OSP from different user interfaces of the identity applications, the users are redirected to the default landing page upon a successful login. When the access token expires within the login session, OSP validates the token and refreshes the session by generating a new access token without the user’s involvement. Otherwise, it directs the user to the login page. Such a trace looks similar to the following:

2016-03-08 06:14:28,509 [http-bio-8443-exec-801] DEBUG com.netiq.idm.auth.oauth.OAuthFilter- [RBPM] Original request going to RBPM is: https://www.snet.acme.com:443/IDMProv/workDashboard.do?apwaLeftNavItem=JSP_MENU_TASKS

2016-03-08 06:15:49,289 [http-bio-8443-exec-816] DEBUG com.netiq.idm.auth.oauth.OAuthFilter- [RBPM] Original request going to RBPM is: https://www.snet.acme.com:443/IDMProv/
2016-03-08 06:15:50,334 [http-bio-8443-exec-815] INFO com.netiq.idm.auth.oauth.OAuthFilter- [RBPM] SSO Header issued by SSO Filter oauth for User cn=Rob.Andrews,ou=Active,ou=People,o=acme.

2016-03-08 06:15:50,354 [http-bio-8443-exec-815] INFO com.novell.common.auth.saml.AuthTokenGenerator- [RBPM] SAML Token is issued by the request from SSO filter oauth

2016-03-08 06:15:50,414 [http-bio-8443-exec-815] INFO com.novell.pwdmgt.util.PasswordHelper- [RBPM] [Login_Success] cn=David.Scully,ou=Active,ou=People,o=acme successfully logged in.

2016-03-08 06:17:53,520 [http-bio-8443-exec-819] DEBUG com.netiq.idm.auth.oauth.OAuthFilter- [RBPM] Original request going to RBPM is: https://www.snet.acme.com:443/IDMProv/

2016-03-08 06:17:55,194 [http-bio-8443-exec-811] INFO com.netiq.idm.auth.oauth.OAuthFilter- [RBPM] SSO Header issued by SSO Filter oauth for User cn=neil.smith,ou=Active,ou=People,o=acme.
2016-03-08 06:17:55,204 [http-bio-8443-exec-811] INFO com.novell.common.auth.saml.AuthTokenGenerator- [RBPM] SAML Token is issued by the request from SSO filter oauth

2016-03-08 06:17:55,234 [http-bio-8443-exec-811] INFO com.novell.pwdmgt.util.PasswordHelper- [RBPM] [Login_Success] cn=neil.smith,ou=Active,ou=People,o=acme successfully logged in.

2016-03-08 06:20:56,616 [http-bio-8443-exec-813] DEBUG com.netiq.idm.auth.oauth.OAuthFilter- [RBPM] Original request going to RBPM is: https://www.snet.acme.com:443/IDMProv/

2016-03-08 06:21:02,129 [http-bio-8443-exec-823] INFO com.netiq.idm.auth.oauth.OAuthFilter- [RBPM] SSO Header issued by SSO Filter oauth for User cn=dean.gardner,ou=Active,ou=People,o=acme.

2016-03-08 06:21:02,149 [http-bio-8443-exec-823] INFO  com.novell.common.auth.saml.AuthTokenGenerator- [RBPM] SAML Token is issued by the request from SSO filter oauth

2016-03-08 06:21:02,216 [http-bio-8443-exec-823] INFO  com.novell.pwdmgt.util.PasswordHelper- [RBPM] [Login_Success] cn=dean.gardner,ou=Active,ou=People,o=acme successfully logged in.

2016-03-08 06:24:28,626 [http-bio-8443-exec-830] DEBUG com.netiq.idm.auth.oauth.OAuthFilter- [RBPM] Original request going to RBPM is: https://www.snet.acme.com:443/IDMProv/workDashboard.do?apwaLeftNavItem=JSP_MENU_TASKS

2016-03-08 06:24:40,547 [http-bio-8443-exec-814] WARN com.netiq.idm.auth.oauth.OAuthManager- [RBPM] Token validation failed. HTTP status code: 401 Detail message from authentication server: The access token is expired.

This trace indicates that the user is accessing the application after some idle time. The last message indicates that the token has expired. When the user tried to log in again, the token failed the validation and as a result the user cannot be logged in.

43.1.5 When an E-Mail Approval Notification is Not Delivered

Sometimes an e-mail notification is not delivered due to errors in the connection between the client and the mail server. When this occurs, the trace looks similar to the following:

2016-03-08 07:42:41,575 [NOTIFICATION THREAD] ERROR com.novell.soa.notification.impl.NotificationThread- [RBPM] Error sending email.
com.novell.soa.notification.impl.NotificationException: Error sending email.
  at com.novell.soa.notification.impl.MailEngine.send(MailEngine.java:347)
at com.novell.soa.notification.impl.NotificationThread.run(NotificationThread.java:96)
Caused by: javax.mail.MessagingException: 421 Too many errors on this connection---closing

  at com.sun.mail.smtp.SMTPTransport.issueCommand(SMTPTransport.java:879)
at com.sun.mail.smtp.SMTPTransport.mailFrom(SMTPTransport.java:599)
  at com.sun.mail.smtp.SMTPTransport.sendMessage(SMTPTransport.java:319)
at com.novell.soa.notification.impl.MailEngine.send(MailEngine.java:344)
  ... 1 more

When an e-mail approval notification is not delivered, the first step should be to look at the logs and determine whether the connection is proper, mail server is running and accessible. Sometimes the e-mail fails to comply with e-mail template and fails to deliver.

43.1.6 When a Role Is Requested

When a role is requested in the identity applications, Identity Manager creates the role object in the Identity Vault. The Role and Resource Service driver checks users for assigning this role, and then provisions the role to the assigned users. When this occurs, the trace prints messages similar to the following:

2016-03-08 08:43:10,660 [pool-2-thread-5] INFO com.novell.idm.nrf.service.RoleManagerService- [RBPM] [Role_Request] Requested by cn=David.Scully,ou=Active,ou=People,o=acme, Target DN: CN=Kaitlin.Demore,OU=active,OU=People,O=acme, Source DN:cn=PennDOT_Vehicle_Certification,cn=Application Access,cn=Level10,cn=RoleDefs,cn=RoleConfig,cn=AppConfig,cn=UserApplication,cn=idm361,ou=services,o=acme, Request DN:cn=20160308084310-15da49b28ddf4ee1b7d71b4ce220c080-0,cn=Requests,cn=RoleConfig,cn=AppConfig,cn=UserApplication,cn=idm361,ou=services,o=acme, Request Category: 10, Request Status: 0, Original Request Status: 0, Correlation ID: UserApp#UserStartWorkflow#082080ec-5b10-498f-b87d-28825ab63278

2016-03-08 08:43:10,669 [pool-2-thread-5] INFO com.novell.idm.nrf.service.RoleManagerService- [RBPM] [Role_Request] Requested by cn=David.Scully,ou=Active,ou=People,o=acme, Target DN: CN=Kaitlin.Demore,OU=active,OU=People,O=acme, Source DN:cn=PennDOT History and Photos Users,cn=Application Access,cn=Level10,cn=RoleDefs,cn=RoleConfig,cn=AppConfig,cn=UserApplication,cn=idm361,ou=services,o=acme, Request DN:cn=20160308084310-3c5b20b79cc046bb8267a41cad88a96a-1,cn=Requests,cn=RoleConfig,cn=AppConfig,cn=UserApplication,cn=idm361,ou=services,o=acme, Request Category: 10, Request Status: 0, Original Request Status: 0, Correlation ID: UserApp#UserStartWorkflow#082080ec-5b10-498f-b87d-28825ab63278

2016-03-08 08:43:10,678 [pool-2-thread-5] INFO  com.novell.idm.nrf.service.RoleManagerService- [RBPM] [Role_Request] Requested by cn=David.Scully,ou=Active,ou=People,o=acme, Target DN: CN=Kaitlin.Demore,OU=active,OU=People,O=acme, Source DN:cn=JWL Eligible Agency,cn=Application Access,cn=Level10,cn=RoleDefs,cn=RoleConfig,cn=AppConfig,cn=UserApplication,cn=idm361,ou=services,o=acme, Request DN:cn=20160308084310-fc24ac874aca4fc8b1db0e1d7662d9b3-2,cn=Requests,cn=RoleConfig,cn=AppConfig,cn=UserApplication,cn=idm361,ou=services,o=acme, Request Category: 10, Request Status: 0, Original Request Status: 0, Correlation ID: UserApp#UserStartWorkflow#082080ec-5b10-498f-b87d-28825ab63278

2016-03-08 08:43:10,712 [pool-2-thread-5] INFO com.novell.idm.nrf.service.RoleManagerService- [RBPM] [Role_Request] Requested by cn=David.Scully,ou=Active,ou=People,o=acme, Target DN: CN=Kaitlin.Demore,OU=active,OU=People,O=acme, Source DN:cn=DPW Recipient Address Eligible Agency,cn=Application Access,cn=Level10,cn=RoleDefs,cn=RoleConfig,cn=AppConfig,cn=UserApplication,cn=idm361,ou=services,o=acme, Request DN:cn=20160308084310-411abb1e8f6f488182c37c8629275245-3,cn=Requests,cn=RoleConfig,cn=AppConfig,cn=UserApplication,cn=idm361,ou=services,o=acme, Request Category: 10, Request Status: 0, Original Request Status: 0, Correlation ID: UserApp#UserStartWorkflow#082080ec-5b10-498f-b87d-28825ab63278

2016-03-08 08:43:10,737 [pool-2-thread-5] INFO com.novell.idm.nrf.service.RoleManagerService- [RBPM] [Role_Request] Requested by cn=David.Scully,ou=Active,ou=People,o=acme, Target DN: CN=Kaitlin.Demore,OU=active,OU=People,O=acme, Source DN:cn=cj-users,cn=Application Access,cn=Level10,cn=RoleDefs,cn=RoleConfig,cn=AppConfig,cn=UserApplication,cn=idm361,ou=services,o=acme, Request DN:cn=20160308084310-211a591e09b04fbbb195fb14d7f4df07-4,cn=Requests,cn=RoleConfig,cn=AppConfig,cn=UserApplication,cn=idm361,ou=services,o=acme, Request Category: 10, Request Status: 0, Original Request Status: 0, Correlation ID: UserApp#UserStartWorkflow#082080ec-5b10-498f-b87d-28825ab63278

2016-03-08 08:43:10,790 [pool-2-thread-5] INFO com.novell.idm.nrf.service.RoleManagerService- [RBPM] [Role_Request] Requested by cn=David.Scully,ou=Active,ou=People,o=acme, Target DN: CN=Kaitlin.Demore,OU=active,OU=People,O=acme, Source DN:cn=JTS Eligible Agency,cn=Application Access,cn=Level10,cn=RoleDefs,cn=RoleConfig,cn=AppConfig,cn=UserApplication,cn=idm361,ou=services,o=acme, Request DN:cn=20160308084310-5339699630814a91ac44530a244a02ba-5,cn=Requests,cn=RoleConfig,cn=AppConfig,cn=UserApplication,cn=idm361,ou=services,o=acme, Request Category: 10, Request Status: 0, Original Request Status: 0, Correlation ID: UserApp#UserStartWorkflow#082080ec-5b10-498f-b87d-28825ab63278

2016-03-08 08:43:10,799 [pool-2-thread-5] INFO com.novell.idm.nrf.service.RoleManagerService- [RBPM] [Role_Request] Requested by cn=David.Scully,ou=Active,ou=People,o=acme, Target DN: CN=Kaitlin.Demore,OU=active,OU=People,O=acme, Source DN:cn=Sentencing Guidelines Eligible Agency,cn=Application Access,cn=Level10,cn=RoleDefs,cn=RoleConfig,cn=AppConfig,cn=UserApplication,cn=idm361,ou=services,o=acme, Request DN:cn=20160308084310-df2398cf36a042f0ac2241e693efb93c-6,cn=Requests,cn=RoleConfig,cn=AppConfig,cn=UserApplication,cn=idm361,ou=services,o=acme, Request Category: 10, Request Status: 0, Original Request Status: 0, Correlation ID: UserApp#UserStartWorkflow#082080ec-5b10-498f-b87d-28825ab63278

2016-03-08 08:43:10,800 [pool-2-thread-5] INFO
com.novell.soa.af.impl.LogEvent- [RBPM] [Role_Request_Submitted] Initiated by cn=David.Scully,ou=Active,ou=People,o=acme, Process ID: 95f25f5f31224efcab1611fe0fc2471f, Process Name: cn=newuserinvitation,cn=RequestDefs,cn=AppConfig,cn=UserApplication,cn=idm361,ou=services,o=acme, Activity: Activity6, Recipient: CN=Kaitlin.Demore,OU=active,OU=People,O=acme, Correlation ID:UserApp#UserStartWorkflow#082080ec-5b10-498f-b87d-28825ab63278, Submitted Request:<?xml version="1.0" encoding="UTF-8"?><wfRoleRequest>
<attr name="sod-override-request">
<value>true</value>
</attr>
<attr name="target">
<value>CN=Kaitlin.Demore,OU=active,OU=People,O=acme</value>
</attr>
<attr name="action">
<value>GRANT</value>
</attr>
<attr name="targetType">
<value>USER</value>
</attr>
<attr name="roles">
<value>cn=PennDOT_Vehicle_Certification,cn=Application Access,cn=Level10,cn=RoleDefs,cn=RoleConfig,cn=AppConfig,cn=UserApplication,ou=services,o=acme</value>
<value>cn=PennDOT History and Photos Users,cn=Application Access,cn=Level10,cn=RoleDefs,cn=RoleConfig,cn=AppConfig,cn=UserApplication,ou=services,o=acme</value>
<value>cn=JWL Eligible Agency,cn=Application Access,cn=Level10,cn=RoleDefs,cn=RoleConfig,cn=AppConfig,cn=UserApplication,ou=services,o=acme</value>
<value>cn=DPW Recipient Address Eligible Agency,cn=Application Access,cn=Level10,cn=RoleDefs,cn=RoleConfig,cn=AppConfig,cn=UserApplication,ou=services,o=acme</value>
<value>cn=cj-users,cn=Application Access,cn=Level10,cn=RoleDefs,cn=RoleConfig,cn=AppConfig,cn=UserApplication,ou=services,o=acme</value>
<value>cn=JTS Eligible Agency,cn=Application Access,cn=Level10,cn=RoleDefs,cn=RoleConfig,cn=AppConfig,cn=UserApplication,ou=services,o=acme</value>
<value>cn=Sentencing Guidelines Eligible Agency,cn=Application Access,cn=Level10,cn=RoleDefs,cn=RoleConfig,cn=AppConfig,cn=UserApplication,ou=services,o=acme</value>
</attr>
<attr name="correlationId">
<value>UserApp#UserStartWorkflow#082080ec-5b10-498f-b87d-28825ab63278</value>
</attr>
<attr name="nrfRequest">
<value>cn=20160308084310-15da49b28ddf4ee1b7d71b4ce220c080-0,cn=Requests,cn=RoleConfig,cn=AppConfig,cn=UserApplication,ou=services,o=acme</value>
<value>cn=20160308084310-3c5b20b79cc046bb8267a41cad88a96a-1,cn=Requests,cn=RoleConfig,cn=AppConfig,cn=UserApplication,ou=services,o=acme</value>
<value>cn=20160308084310-fc24ac874aca4fc8b1db0e1d7662d9b3-2,cn=Requests,cn=RoleConfig,cn=AppConfig,cn=UserApplication,ou=services,o=acme</value>
<value>cn=20160308084310-411abb1e8f6f488182c37c8629275245-3,cn=Requests,cn=RoleConfig,cn=AppConfig,cn=UserApplication,ou=services,o=acme</value>
<value>cn=20160308084310-211a591e09b04fbbb195fb14d7f4df07-4,cn=Requests,cn=RoleConfig,cn=AppConfig,cn=UserApplication,ou=services,o=acme</value>
<value>cn=20160308084310-5339699630814a91ac44530a244a02ba-5,cn=Requests,cn=RoleConfig,cn=AppConfig,cn=UserApplication,ou=services,o=acme</value>
<value>cn=20160308084310-df2398cf36a042f0ac2241e693efb93c-6,cn=Requests,cn=RoleConfig,cn=AppConfig,cn=UserApplication,ou=services,o=acme</value>
</attr>
</wfRoleRequest>

2016-03-08 08:43:10,880 [pool-2-thread-5] INFO com.novell.soa.af.impl.LogEvent- [RBPM] [Workflow_Forwarded] Initiated by System, Process ID: 95f25f5f31224efcab1611fe0fc2471f, Process Name: cn=newuserinvitation,cn=RequestDefs,cn=AppConfig,cn=UserApplication,ou=services,o=acme:205, Activity: Activity6, Recipient: cn=Nancy.Wilmer,ou=Active,ou=People,o=acme

43.1.7 When a Role Is Listed in Role Catalog

When you issue a request to display a role in Role Catalog, the identity applications obtain the role object from the cache and then display the role information in Role Catalog.

2017-09-22 09:28:26,495 [DEBUG] RuntimeAuthorizationManagerService [RBPM] Authorized result for: cn=roleAdmin,cn=System,cn=Level20,cn=RoleDefs,cn=RoleConfig,cn=AppConfig,cn=User Application Driver,cn=driverset1,o=system:role:read=true

2017-09-22 09:28:26,495 [DEBUG] CacheUtil [RBPM] Role object was found in cache: cache-key-nrf-config

2017-09-22 09:28:26,495 [DEBUG] CacheUtil [RBPM] Role object RETRIEVED from cache: cache-key-nrf-config

2017-09-22 09:28:26,509 [DEBUG] RuntimeAuthDelegatorBase [RBPM] Time to calculate sel service access rights: 0milliseconds.

2017-09-22 09:28:26,509 [DEBUG] RuntimeAuthorizationManagerService [RBPM] Authorized result for: cn=secAdmin,cn=System,cn=Level20,cn=RoleDefs,cn=RoleConfig,cn=AppConfig,cn=User Application Driver,cn=driverset1,o=system:role:read=true

2017-09-22 09:28:26,510 [DEBUG] CacheUtil [RBPM] Role object was found in cache: cache-key-nrf-config

2017-09-22 09:28:26,510 [DEBUG] CacheUtil [RBPM] Role object RETRIEVED from cache: cache-key-nrf-config

2017-09-22 09:28:26,522 [DEBUG] RuntimeAuthDelegatorBase [RBPM] Time to calculate sel service access rights: 0milliseconds.

2017-09-22 09:28:26,522 [DEBUG] RuntimeAuthorizationManagerService [RBPM] Authorized result for: cn=resourceManager,cn=System,cn=Level20,cn=RoleDefs,cn=RoleConfig,cn=AppConfig,cn=User Application Driver,cn=driverset1,o=system:role:read=true

2017-09-22 09:28:26,522 [DEBUG] CacheUtil [RBPM] Role object was found in cache: cache-key-nrf-config

2017-09-22 09:28:26,522 [DEBUG] CacheUtil [RBPM] Role object RETRIEVED from cache: cache-key-nrf-config

2017-09-22 09:28:26,533 [DEBUG] RuntimeAuthDelegatorBase [RBPM] Time to calculate sel service access rights: 0milliseconds.

2017-09-22 09:28:26,533 [DEBUG] RuntimeAuthorizationManagerService [RBPM] Authorized result for: cn=roleManager,cn=System,cn=Level20,cn=RoleDefs,cn=RoleConfig,cn=AppConfig,cn=User Application Driver,cn=driverset1,o=system:role:read=true

2017-09-22 09:28:26,534 [DEBUG] CacheUtil [RBPM] Role object was found in cache: cache-key-nrf-config

2017-09-22 09:28:26,534 [DEBUG] CacheUtil [RBPM] Role object RETRIEVED from cache: cache-key-nrf-config

2017-09-22 09:28:26,545 [DEBUG] RuntimeAuthDelegatorBase [RBPM] Time to calculate sel service access rights: 0milliseconds.

2017-09-22 09:28:26,545 [DEBUG] RuntimeAuthorizationManagerService [RBPM] Authorized result for: cn=resourceAdmin,cn=System,cn=Level20,cn=RoleDefs,cn=RoleConfig,cn=AppConfig,cn=User Application Driver,cn=driverset1,o=system:role:read=true

2017-09-22 09:28:26,545 [DEBUG] CacheUtil [RBPM] Role object was found in cache: cache-key-nrf-config

2017-09-22 09:28:26,545 [DEBUG] CacheUtil [RBPM] Role object RETRIEVED from cache: cache-key-nrf-config

2017-09-22 09:28:26,557 [DEBUG] RuntimeAuthDelegatorBase [RBPM] Time to calculate sel service access rights: 0milliseconds.

2017-09-22 09:28:26,557 [DEBUG] RuntimeAuthorizationManagerService [RBPM] Authorized result for: cn=provAdmin,cn=System,cn=Level20,cn=RoleDefs,cn=RoleConfig,cn=AppConfig,cn=User Application Driver,cn=driverset1,o=system:role:read=true

2017-09-22 09:28:26,557 [DEBUG] CacheUtil [RBPM] Role object was found in cache: cache-key-nrf-config

2017-09-22 09:28:26,557 [DEBUG] CacheUtil [RBPM] Role object RETRIEVED from cache: cache-key-nrf-config

2017-09-22 09:28:26,567 [DEBUG] RuntimeAuthDelegatorBase [RBPM] Time to calculate sel service access rights: 0milliseconds.

2017-09-22 09:28:26,567 [DEBUG] RuntimeAuthorizationManagerService [RBPM] Authorized result for: cn=reportAdmin,cn=System,cn=Level20,cn=RoleDefs,cn=RoleConfig,cn=AppConfig,cn=User Application Driver,cn=driverset1,o=system:role:read=true

2017-09-22 09:28:26,567 [DEBUG] CacheUtil [RBPM] Role object was found in cache: cache-key-nrf-config

2017-09-22 09:28:26,567 [DEBUG] CacheUtil [RBPM] Role object RETRIEVED from cache: cache-key-nrf-config

2017-09-22 09:28:26,582 [DEBUG] RuntimeAuthDelegatorBase [RBPM] Time to calculate sel service access rights: 0milliseconds.

2017-09-22 09:28:26,582 [DEBUG] RuntimeAuthorizationManagerService [RBPM] Authorized result for: cn=provManager,cn=System,cn=Level20,cn=RoleDefs,cn=RoleConfig,cn=AppConfig,cn=User Application Driver,cn=driverset1,o=system:role:read=true

2017-09-22 09:28:26,582 [DEBUG] JuiceHelper [RBPM] Kicked out of main loop with: openR=-1 closeR=-1 i=0 idx=-1

2017-09-22 09:28:26,582 [DEBUG] JuiceHelper [RBPM] Setting RsMeta from cache: METAlistRoles_defaultDescription&*~Name&*~enStatus_cn=uaadmin,ou=sa,o=data

2017-09-22 09:28:26,583 [DEBUG] VirtualDataModel [RBPM] VDM.getEntityDefinition(String, Locale):sys-nrf-role

2017-09-22 09:28:26,583 [DEBUG] CacheUtil [RBPM] DAL Definition RETRIEVED from cache: VDM_ENTITY_DEFINITION_sys-nrf-role

2017-09-22 09:28:26,583 [DEBUG] CacheUtil [RBPM] DAL Definition RETRIEVED from cache: VDM_DEFINITION_ATTRIBUTE_LIST_sys-nrf-role

2017-09-22 09:28:26,583 [DEBUG] CacheUtil [RBPM] Role object was found in cache: cache-key-nrf-config

2017-09-22 09:28:26,583 [DEBUG] CacheUtil [RBPM] Role object RETRIEVED from cache: cache-key-nrf-config

The first log entry is the request to find the role object from the cache. The second log entry is the response that is returned, and it indicates that the role object was found. The object is then read and displayed in Role Catalog.

43.1.8 Schema Fails to Update When Updated Using a User Account That Was Not Used to Create the Schema

If Identity Applications use a different user account to update the schema than the account that was used to initially create it, the schema fails to update. It reports the following error in the catalina.out file:

2018-06-11 15:47:37,956 [localhost-startStop-1] INFO  liquibase- liquibase: Clearing database change log checksums
2018-06-11 15:47:39,051 [localhost-startStop-1] ERROR com.sssw.fw.servlet.EboBootServlet- [RBPM] Runtime exception initializing.
com.netiq.persist.PersistenceException: ORA-01031: insufficient privileges
                at com.novell.soa.persist.DatabaseSchemaUpdate.unappliedChangeSets(DatabaseSchemaUpdate.java:365)
                at com.novell.soa.persist.DatabaseSchemaUpdate.validateDatabaseSchema(DatabaseSchemaUpdate.java:229)
                at com.sssw.fw.servlet.EboBootServlet.init(EboBootServlet.java:98)
                at com.sssw.portal.servlet.EboPortalBootServlet.init(EboPortalBootServlet.java:59)
                at javax.servlet.GenericServlet.init(GenericServlet.java:158)
                at org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:1284)
                at org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1197)
                at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:1087)
                at org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:5229)
                at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5516)
                at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
                at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:901)
                at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:877)
                at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:649)
                at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:1083)
                at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:1880)
                at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
                at java.util.concurrent.FutureTask.run(FutureTask.java:266)
                at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
                at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
                at java.lang.Thread.run(Thread.java:745)
Caused by: liquibase.exception.LockException: liquibase.exception.DatabaseException: Error executing SQL CREATE TABLE ora_user_id.DATABASECHANGELOGLOCK (ID NUMBER(10) NOT NULL, LOCKED NUMBER(1) NOT NULL, LOCKGRANTED TIMESTAMP, LOCKEDBY NVARCHAR2(255), CONSTRAINT PK_DATABASECHANGELOGLOCK PRIMARY KEY (ID)): ORA-01031: insufficient privileges
                at liquibase.lockservice.StandardLockService.acquireLock(StandardLockService.java:209)
                at liquibase.lockservice.StandardLockService.waitForLock(StandardLockService.java:148)
                at liquibase.Liquibase.clearCheckSums(Liquibase.java:886)
                at com.novell.soa.persist.DatabaseSchemaUpdate.unappliedChangeSets(DatabaseSchemaUpdate.java:340)
                ... 20 more

To resolve this issue, set the following Java system properties for Liquibase in the setenv startup script at /opt/netiq/idm/apps/tomcat/bin/ or c:\NetIQ\idm\apps\tomcat\bin:

  • -Dliquibase.schemaName={schema_owner_id}

  • -Dliquibase.catalogName={schema_owner_id}

43.1.9 Checking the Status of Database Schema Validation

The identity applications database schema is validated when the administrator starts the identity applications server. The trace prints messages similar to the following:

2017-09-22 09:39:41,363 [INFO] DatabaseSchemaUpdate [RBPM] Connecting to PostgreSQL version 9.4.10.

2017-09-22 09:39:41,375 [INFO] DatabaseSchemaUpdate [RBPM] Checking for database schema

2017-09-22 09:39:41,401 [INFO] DatabaseSchemaUpdate [RBPM] Checking schema for table af_resource_request_status....found

2017-09-22 09:39:41,422 [INFO] DatabaseSchemaUpdate [RBPM] Checking schema for table af_role_request_status....found

2017-09-22 09:39:41,481 [INFO] DatabaseSchemaUpdate [RBPM] Checking schema for table afactivity....found

2017-09-22 09:39:41,501 [INFO] DatabaseSchemaUpdate [RBPM] Checking schema for table afactivitytimertasks....found

2017-09-22 09:39:41,576 [INFO] DatabaseSchemaUpdate [RBPM] Checking schema for table afbranch....found

2017-09-22 09:39:41,612 [INFO] DatabaseSchemaUpdate [RBPM] Checking schema for table afcomment....found

2017-09-22 09:39:41,651 [INFO] DatabaseSchemaUpdate [RBPM] Checking schema for table afdocument....missing

The first log entry indicates that a connection to the database is initiated. The second log entry specifies that the database schema is being validated. The subsequent entries specify that the presence of database tables is being checked. The last trace entry indicates that afdocument table is not found.

43.1.10 Determining if Liquibase Changeset Has Executed

The Liquibase framework validates the database schema against the changelog.xml file, which contains the database changes. Liquibase first verifies whether all the tables are present in the schema. If any of the changesets was not executed, it indicates incomplete schema update and also identifies the changesets. Any schema changes made in the User Application are updated in the database when the User Application server is started and com.netiq.idm.create-db-on-startup flag is set to true in the ism-configuration properties file located by default in the /netiq/idm/apps/tomcat/conf directory. The database compares the existing schema with target schema and then updates the database schema. If the flag is not set, it reports the following message:

One or more required tables are missing. Check log for messages indicating tables that were not found.

When Liquibase validates the database schema, it generates log entries similar to the following:

2017-09-22 09:39:47,693 [INFO] liquibase liquibase: Reading from public.databasechangelog

2017-09-22 09:39:49,133 [INFO] liquibase liquibase: Reading from public.databasechangelog

2017-09-22 09:39:49,427 [INFO] liquibase liquibase: Reading from public.databasechangelog

2017-09-22 09:39:49,551 [INFO] liquibase liquibase: Reading from public.databasechangelog

2017-09-22 09:39:50,095 [INFO] liquibase liquibase: Reading from public.databasechangelog

2017-09-22 09:39:50,403 [INFO] liquibase liquibase: Reading from public.databasechangelog

2017-09-22 09:39:50,514 [ERROR] EboPortalBootServlet [RBPM] Unexpected Runtime Exception initializing servlet
java.lang.RuntimeException: com.netiq.common.i18n.LocalizedRuntimeException: Schema is invalid. One or more required tables are missing. Check log for messages indicating tables that were not found.
        at com.sssw.fw.servlet.EboBootServlet.init(EboBootServlet.java:115)
        at com.sssw.portal.servlet.EboPortalBootServlet.init(EboPortalBootServlet.java:62)
        at javax.servlet.GenericServlet.init(GenericServlet.java:158)
        at org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:1183)
        at org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1099)
        at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:989)
        at org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:4913)
        at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5223)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:752)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:728)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:734)
        at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:952)
        at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:1823)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)
Caused by: com.netiq.common.i18n.LocalizedRuntimeException: Schema is invalid. One or more required tables are missing. Check log for messages indicating tables that were not found.
        at com.novell.soa.persist.DatabaseSchemaUpdate.validateDatabaseSchema(DatabaseSchemaUpdate.java:245)
        at com.sssw.fw.servlet.EboBootServlet.init(EboBootServlet.java:99) ... 18 more

Sep 22, 2017 9:39:50 AM org.apache.catalina.core.StandardContext loadOnStartup
SEVERE: Servlet [PortalAggregator] in web application [/IDMProv] threw load() exception java.lang.NullPointerException at com.sssw.portal.manager.EboPortalManager.<init>(EboPortalManager.java:179)

You must restart the application server to apply the changes. You cannot bring up the identity applications until the schema validation succeeds.

43.1.11 When Assigning a Resource to a User That Does Not Exist

If a user no longer exists in the system, and a request is issued to assign a resource to that user, the trace records messages similar to the following:

2017-09-22 11:50:53,605 [DEBUG] DataItemEvaluator [RBPM] result: Add Resource To User - Laptop

2017-09-22 11:50:53,607 [ERROR] VirtualDataAccess [RBPM] Error occurred checking the object type for: cn=rocio,ou=users,o=data
javax.naming.NameNotFoundException: [LDAP: error code 32 - NDS error: no such entry (-601)]; remaining name 'cn=rocio,ou=users,o=data'
        at com.sun.jndi.ldap.LdapCtx.mapErrorCode(LdapCtx.java:3161)
        at com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:3082)
        at com.sun.jndi.ldap.LdapCtx.processReturnCode(LdapCtx.java:2888)
        at com.sun.jndi.ldap.LdapCtx.c_getAttributes(LdapCtx.java:1329)
        at com.sun.jndi.toolkit.ctx.ComponentDirContext.p_getAttributes(ComponentDirContext.java:235)
        at com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.getAttributes(PartialCompositeDirContext.java:141)
        at com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.getAttributes(PartialCompositeDirContext.java:129)
        at sun.reflect.GeneratedMethodAccessor432.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at com.sssw.fw.directory.realm.impl.jndildap.EboLdapContextProxyHandler.invokeMethod(EboLdapContextProxyHandler.java:145)
        at com.sssw.fw.directory.realm.impl.jndildap.EboLdapContextProxyHandler.invoke(EboLdapContextProxyHandler.java:86)
        at com.sun.proxy.$Proxy155.getAttributes(Unknown Source)
        at com.novell.srvprv.impl.vdata.model.VirtualDataAccess.getObjectType(VirtualDataAccess.java:3943)
        at com.novell.srvprv.impl.vdata.model.VirtualDataAccess.getObjectType(VirtualDataAccess.java:4003)
        at com.novell.srvprv.impl.vdata.model.VirtualDataModel.getObjectType(VirtualDataModel.java:1405)
        at com.novell.soa.util.LdapUtil.isTypeOf(LdapUtil.java:109)
        at com.novell.soa.util.LdapUtil.isUser(LdapUtil.java:89)

The trace displays object unavailable errors only when errors occur while retrieving an object.

43.1.12 When Checking the Workflow Engine Heartbeat

The following are example entries that are logged when a user issues a request to check the state of the workflow engine.

2017-09-22 11:53:33,646 [TRACE] EngineStateDAO [RBPM] Updating heartbeat of Engine Engine State: engineId = ENGINE, heartBeat= 
2017-09-22 11:52:33.637, startTime= 2017-09-22 09:55:31.532, shutdownTime= 2017-09-22 09:52:58.773, engineState= Running

2017-09-22 11:53:33,647 [DEBUG] HibernateUtil [RBPM] Beginning new transaction for caller com.novell.soa.af.impl.persist.EngineStateDAO:141

2017-09-22 11:53:33,652 [TRACE] EngineStateDAO [RBPM] Engine heartbeat updated successfully: Engine State: engineId = ENGINE, heartBeat= 2017-09-22 11:53:33.651, startTime= 2017-09-22 09:55:31.532, shutdownTime= 2017-09-22 09:52:58.773, engineState= Running

2017-09-22 11:53:33,660 [DEBUG] HibernateUtil [RBPM] Committed transaction for caller com.novell.soa.af.impl.persist.EngineStateDAO:162

2017-09-22 11:53:33,660 [DEBUG] EngineImpl [RBPM] Heartbeat updated for engine: ENGINE, time: 2017-09-22 11:53:33.651

2017-09-22 11:54:03,017 [DEBUG] HibernateUtil [RBPM] Beginning new transaction for caller com.novell.soa.af.impl.timers.PendingActivityTimerTask:94

2017-09-22 11:54:03,018 [DEBUG] HibernateUtil [RBPM] Committed transaction for caller com.novell.soa.af.impl.timers.PendingActivityTimerTask:94

If the workflow engine is not properly shutdown due to some reason, the identity applications assume that the engine is still running when you start it the next time. The following example traces are logged to indicate this situation.

2017-09-22 12:01:43,384 [WARN] EngineImpl [RBPM] Duplicate engine id detected. This engine may not have been shutdown cleanly or another engine is running with engine-id: ENGINE. Waiting 60000 ms for heartbeat to timeout.

2017-09-22 12:01:43,480 [INFO] EngineImpl [RBPM] Workflow Engine setState: [RUNNING]

43.1.13 catalina.out File Does Not Rotate the Log on Linux

On Linux, logrotate utility handles the log rotation of catalina.out file. The log rotation configuration is stored in the netiq-tomcat file in /etc/logrotate.d directory. If logrotate is not scheduled to run daily, the logs are not rotated. NetIQ recommends you to rotate the logs at 12:00 a.m (midnight).

If SELinux is configured to run in Enforcing mode, logrotate might not work as expected.

Workaround: Run the following command:

semanage fcontext -a -t var_log_t '/opt/netiq/idm/apps/tomcat/logs(/.*)?'
restorecon -Frvv /opt/netiq/idm/apps/tomcat/logs