000033429 - How to turn on debug logging for a RSA Identity Governance and Lifecycle Access Fulfillment Express (AFX) Connector 7.0, 6.9.1 and 6.8.1

Document created by RSA Customer Support Employee on Jun 28, 2016•Last modified by RSA Customer Support Employee on Mar 20, 2017
Version 2Show Document
  • Comment • 0
  • View in full screen mode

Article Content

Article Number000033429
Applies ToRSA Product Set: RSA Identity Governance and Lifecycle
RSA Version/Condition: 6.8.1, 6.9.1, and 7.0
Platform: Any
IssueThe Access Fulfilment Express (AFX) output into the mule.AFX-CONN-<CONNECTOR_NAME>.log in previous versions of the product (prior to RSA IMG 6.8.1/AFX 2.8.1), provided detailed information on the specific success and failure messages of AFX commands to and from an endpoint. To obtain that level of information in the current versions, debug logging needs to be enabled.
An example of the AFX connector log naming syntax is as follows:
 
/home/oracle/AFX/mule/logs/mule.AFX-CONN-<CONNECTOR_NAME>.log

This is very useful when troubleshooting or debugging an AFX connector.
There is quite a bit of logging output into the following logs but it generally does not provide the level of detail required to troubleshoot a specific AFX connector.  These logs are:
  • /home/oracle/AFX/mule/logs/mule_ee.log,
  • /home/oracle/AFX/mule/logs/mule.AFX-MAIN.log, and
  • /home/oracle/AFX/mule/logs/agent.log.
ResolutionTo enable debug,
  1. Edit the /home/oracle/AFX/mule/apps/AFX-CONN-<CONNECTOR_NAME>/classes/log4j.xml to change the log level from INFO to DEBUG.  An example of the file path is /home/oracle/AFX/mule/apps/AFX-CONN-AD_AFX_Connector_NO_Prov_Node/classes/log4j.xml.
  2. Edit the .xml using the following syntax: 
<logger name="org.mule.api.processor.LoggerMessageProcessor"> 
<!-- <level value="INFO"/> --> 
<level value="DEBUG"/> 
</logger>

  1. For changes to take effect immediately, touch the /home/oracle/AFX/mule/apps/AFX-CONN-<CONNECTOR_NAME>/mule-config.xml file.  An example of the file path is /home/oracle/AFX/mule/apps/AFX-CONN-AD_AFX_Connector_NO_Prov_Node/mule-config.xml.
oracle@server:~> cd /home/oracle/AFX/mule/apps/AFX-CONN-AD_AFX_Connector_No_Prov_Node/
oracle@server:~/AFX/mule/apps/AFX-CONN-AD_AFX_Connector_No_Prov_Node> touch mule-config.xml

  1. Do not restart the AFX server or edit the AFX connector from the UI, as it will override the settings made above. 
  2. The next time you use the connector (or test the capabilities), you will see the result output in the mule.AFX-CONN-<CONNECTOR_NAME>.log.  As an example, /home/oracle/AFX/mule/logs/mule.AFX-CONN-AD_AFX_Connector_NO_Prov_Node.log.
NotesThe example below shows what the stack trace output looks like:
 
2015-05-12 11:39:16.688 [DEBUG] org.mule.api.processor.LoggerMessageProcessor:125 - XML Payload from JMS: <?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<ns2:Envelope xmlns:ns2="http://aveksa.com/afx/messages/primary" xmlns:ns3="http://aveksa.com/afx/messages/initialization">
    <Header>
        <version>1.0</version>
        <appid>ACM</appid>
        <crid>NA</crid>
        <type>response</type>
        <callback>NA</callback>
        <afxid>d8be44d0-d5d8-4d4c-a18c-1f5b1c630e25</afxid>
        <async-callback>false</async-callback>
        <async-callback-url>http://localhost:8089/callback/d8be44d0-d5d8-4d4c-a18c-1f5b1c630e25</async-callback-url>
        <testmessage>true</testmessage>
        <passthruvalues>
            <passthruvalue name="TestKey">f8340188-0687-45dc-8d0a-3ea7cc558d02</passthruvalue>
        </passthruvalues>
    </Header>
    <Body>
        <Request timestamp="
2015-05-12T11:39:10.660-04:00" id="1">
            <epid>AD_AFX_Connector_NO_Prov_Node</epid>
            <verb name="AddAccountToGroup">
                <parameters>
                    <parameter name="Account">user_id01</parameter>
                    <parameter name="Group">Group02</parameter>
                </parameters>
            </verb>
            <Response timestamp="
2015-05-12T11:39:16.665-04:00">
                <status>
                    <code>0</code>
                    <brief>Success</brief>
                    <detailed></detailed>
                </status>
            </Response>
        </Request>
    </Body>
</ns2:Envelope>
2015-05-12 11:39:16.698 [INFO] org.mule.transport.service.DefaultTransportServiceDescriptor:197 - Loading default outbound transformer: org.mule.transport.jms.transformers.ObjectToJMSMessage
2015-05-12 11:39:16.711 [INFO] org.mule.transport.service.DefaultTransportServiceDescriptor:197 - Loading default response transformer: org.mule.transport.jms.transformers.ObjectToJMSMessage
2015-05-12 11:39:16.712 [WARN] com.mulesoft.mule.transport.jms.EeJmsMessageDispatcher:269 - Starting patched JmsMessageReceiver
2015-05-12 11:39:16.712 [INFO] org.mule.lifecycle.AbstractLifecycleManager:197 - Initialising: 'fulfillmentStateJmsConnector.dispatcher.457440913'. Object is: EeJmsMessageDispatcher
2015-05-12 11:39:16.712 [INFO] org.mule.lifecycle.AbstractLifecycleManager:197 - Starting: 'fulfillmentStateJmsConnector.dispatcher.457440913'. Object is: EeJmsMessageDispatcher
2015-05-12 11:39:16.787 [DEBUG] org.mule.api.processor.LoggerMessageProcessor:125 - LDAP Group: CN=Group02,OU=AveksaLab01,DC=aveksa-support,DC=local
2015-05-12 11:39:16.912 [INFO] org.mule.transport.ldapx.transformers.MessageToModifyRequest:197 - DN: CN=Group02,OU=AveksaLab01,DC=aveksa-support,DC=local
2015-05-12 11:39:16.912 [INFO] org.mule.transport.ldapx.transformers.MessageToModifyRequest:197 - UID: CN=Group02
2015-05-12 11:39:16.913 [INFO] org.mule.transport.ldapx.transformers.MessageToModifyRequest:197 - UID FILTER: (CN=Group02)
2015-05-12 11:39:16.913 [INFO] org.mule.transport.ldapx.transformers.MessageToModifyRequest:197 - BASE: OU=AveksaLab01,DC=aveksa-support,DC=local
2015-05-12 11:39:17.008 [DEBUG] org.mule.api.processor.LoggerMessageProcessor:125 - LDAP Payload: [UNIVERSAL 16] SEQUENCE: { [UNIVERSAL 2] INTEGER: 6, [APPLICATION 6] SEQUENCE: { [UNIVERSAL 4] OCTET STRING: CN=Group02,OU=AveksaLab01,DC=aveksa-support,DC=local, [UNIVERSAL 16] SEQUENCE OF: { [UNIVERSAL 16] SEQUENCE: { [UNIVERSAL 10] ENUMERATED: 0, [UNIVERSAL 16] SEQUENCE: { [UNIVERSAL 4] OCTET STRING: member, [UNIVERSAL 17] SET OF: { [UNIVERSAL 4] OCTET STRING: CN=user_id01,OU=AveksaLab01,DC=aveksa-support,DC=local } } } } } }
2015-05-12 11:39:17.010 [INFO] org.mule.lifecycle.AbstractLifecycleManager:197 - Initialising: 'AD_AFX_Connector_NO_Prov_Node.LDAP.connector.dispatcher.1883340558'. Object is: LdapxMessageDispatcher
2015-05-12 11:39:17.012 [INFO] org.mule.lifecycle.AbstractLifecycleManager:197 - Starting: 'AD_AFX_Connector_NO_Prov_Node.LDAP.connector.dispatcher.1883340558'. Object is: LdapxMessageDispatcher
2015-05-12 11:39:17.103 [ERROR] org.mule.transport.ldapx.LdapxConnector:341 - Error: No such object
2015-05-12 11:39:17.114 [ERROR] org.mule.exception.DefaultMessagingExceptionStrategy:341 - 
********************************************************************************
Message               : Failed to route event via endpoint: DefaultOutboundEndpoint{endpointUri=ldapx://AD_AFX_Connector_NO_Prov_Node.LDAP, connector=LdapxConnector
{
  name=AD_AFX_Connector_NO_Prov_Node.LDAP.connector
  lifecycle=start
  this=372caf28
  numberOfConcurrentTransactedReceivers=4
  createMultipleTransactedReceivers=true
  connected=true
  supportedProtocols=[ldapx]
  serviceOverrides=<none>
}
,  name='endpoint.ldapx.AD.AFX.Connector.NO.Prov.Node.LDAP', mep=REQUEST_RESPONSE, properties={}, transactionConfig=Transaction{factory=null, action=INDIFFERENT, timeout=0}, deleteUnacceptedMessages=false, initialState=started, responseTimeout=10000, endpointEncoding=UTF-8, disableTransportTransformer=false}. Message payload is of type: LDAPModifyRequest
Code                  : MULE_ERROR-42999
--------------------------------------------------------------------------------
Exception stack is:
1. No Such Object (com.novell.ldap.LDAPException)
  com.novell.ldap.LDAPResponse:-1 (null)
2. Failed to route event via endpoint: DefaultOutboundEndpoint{endpointUri=ldapx://AD_AFX_Connector_NO_Prov_Node.LDAP, connector=LdapxConnector
{
  name=AD_AFX_Connector_NO_Prov_Node.LDAP.connector
  lifecycle=start
  this=372caf28
  numberOfConcurrentTransactedReceivers=4
  createMultipleTransactedReceivers=true
  connected=true
  supportedProtocols=[ldapx]
  serviceOverrides=<none>
}
,  name='endpoint.ldapx.AD.AFX.Connector.NO.Prov.Node.LDAP', mep=REQUEST_RESPONSE, properties={}, transactionConfig=Transaction{factory=null, action=INDIFFERENT, timeout=0}, deleteUnacceptedMessages=false, initialState=started, responseTimeout=10000, endpointEncoding=UTF-8, disableTransportTransformer=false}. Message payload is of type: LDAPModifyRequest (org.mule.api.transport.DispatchException)
  org.mule.transport.AbstractMessageDispatcher:109 (http://www.mulesoft.org/docs/site/current3/apidocs/org/mule/api/transport/DispatchException.html)
--------------------------------------------------------------------------------
Root Exception stack trace:
LDAPException: No Such Object (32) No Such Object
LDAPException: Server Message: 00000525: NameErr: DSID-031A11CC, problem 2001 (NO_OBJECT), data 0, best match of:
    ''
LDAPException: Matched DN: 
    at com.novell.ldap.LDAPResponse.getResultException(Unknown Source)
    at com.novell.ldap.LDAPResponse.chkResultCode(Unknown Source)
    at com.novell.ldap.LDAPConnection.chkResultCode(Unknown Source)
    + 3 more (set debug level logging or '-Dmule.verbose.exceptions=true' for everything)
********************************************************************************
2015-05-12 11:39:17.115 [INFO] org.mule.api.processor.LoggerMessageProcessor:197 - AD_AFX_Connector_NO_Prov_Node.EXCEPTION flow invoked...
2015-05-12 11:39:17.116 [INFO] org.mule.api.processor.LoggerMessageProcessor:197 - Not account created, no cleanup required!
2015-05-12 11:39:17.163 [INFO] org.mule.api.processor.LoggerMessageProcessor:197 - AFX_OUT redirect flow invoked...
2015-05-12 11:39:17.179 [INFO] org.mule.transport.service.DefaultTransportServiceDescriptor:197 - Loading default outbound transformer: org.mule.transport.jms.transformers.ObjectToJMSMessage
2015-05-12 11:39:17.180 [INFO] org.mule.transport.service.DefaultTransportServiceDescriptor:197 - Loading default response transformer: org.mule.transport.jms.transformers.ObjectToJMSMessage
2015-05-12 11:39:17.181 [WARN] com.mulesoft.mule.transport.jms.EeJmsMessageDispatcher:269 - Starting patched JmsMessageReceiver
2015-05-12 11:39:17.181 [INFO] org.mule.lifecycle.AbstractLifecycleManager:197 - Initialising: 'jmsConnector.dispatcher.1927513024'. Object is: EeJmsMessageDispatcher
2015-05-12 11:39:17.183 [INFO] org.mule.lifecycle.AbstractLifecycleManager:197 - Starting: 'jmsConnector.dispatcher.1927513024'. Object is: EeJmsMessageDispatcher
2015-05-12 11:44:06.341 [DEBUG] org.mule.api.processor.LoggerMessageProcessor:125 - XML Payload from JMS: <?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<ns2:Envelope xmlns:ns2="http://aveksa.com/afx/messages/primary" xmlns:ns3="http://aveksa.com/afx/messages/initialization">
    <Header>
        <version>1.0</version>
        <appid>ACM</appid>
        <crid>NA</crid>
        <type>response</type>
        <callback>NA</callback>
        <afxid>6edf6295-db0d-43b1-a060-a2580f2bae86</afxid>
        <async-callback>false</async-callback>
        <async-callback-url>http://localhost:8089/callback/6edf6295-db0d-43b1-a060-a2580f2bae86</async-callback-url>
        <testmessage>true</testmessage>
        <passthruvalues>
            <passthruvalue name="TestKey">02a9f89d-4dcf-41d6-b0f3-7ab109c3d815</passthruvalue>
        </passthruvalues>
    </Header>
    <Body>
        <Request timestamp="
2015-05-12T11:43:56.585-04:00" id="1">
            <epid>AD_AFX_Connector_NO_Prov_Node</epid>
            <verb name="AddAccountToGroup">
                <parameters>
                    <parameter name="Account">user_id2</parameter>
                    <parameter name="Group">Group02</parameter>
                </parameters>
            </verb>
            <Response timestamp="
2015-05-12T11:44:06.332-04:00">
                <status>
                    <code>0</code>
                    <brief>Success</brief>
                    <detailed></detailed>
                </status>
            </Response>
        </Request>
    </Body>
</ns2:Envelope>
2015-05-12 11:44:06.357 [DEBUG] org.mule.api.processor.LoggerMessageProcessor:125 - LDAP Group: CN=Group02,OU=AveksaLab01,DC=aveksa-support,DC=local
2015-05-12 11:44:06.358 [INFO] org.mule.transport.ldapx.transformers.MessageToModifyRequest:197 - DN: CN=Group02,OU=AveksaLab01,DC=aveksa-support,DC=local
2015-05-12 11:44:06.358 [INFO] org.mule.transport.ldapx.transformers.MessageToModifyRequest:197 - UID: CN=Group02
2015-05-12 11:44:06.359 [INFO] org.mule.transport.ldapx.transformers.MessageToModifyRequest:197 - UID FILTER: (CN=Group02)
2015-05-12 11:44:06.359 [INFO] org.mule.transport.ldapx.transformers.MessageToModifyRequest:197 - BASE: OU=AveksaLab01,DC=aveksa-support,DC=local
2015-05-12 11:44:06.365 [DEBUG] org.mule.api.processor.LoggerMessageProcessor:125 - LDAP Payload: [UNIVERSAL 16] SEQUENCE: { [UNIVERSAL 2] INTEGER: 12, [APPLICATION 6] SEQUENCE: { [UNIVERSAL 4] OCTET STRING: CN=Group02,OU=AveksaLab01,DC=aveksa-support,DC=local, [UNIVERSAL 16] SEQUENCE OF: { [UNIVERSAL 16] SEQUENCE: { [UNIVERSAL 10] ENUMERATED: 0, [UNIVERSAL 16] SEQUENCE: { [UNIVERSAL 4] OCTET STRING: member, [UNIVERSAL 17] SET OF: { [UNIVERSAL 4] OCTET STRING: CN=user_id2,OU=AveksaLab01,DC=aveksa-support,DC=local } } } } } }
2015-05-12 11:44:06.454 [INFO] org.mule.api.processor.LoggerMessageProcessor:197 - Adding group DN to user entry not required 
2015-05-12 11:44:06.456 [INFO] org.mule.api.processor.LoggerMessageProcessor:197 - AFX_OUT redirect flow invoked...

Attachments

    Outcomes