Thursday, October 20, 2016

WSO2 ESB Log Files Explained

WSO2 ESB is generating several log files during its operation. This post will describe the usage of these logs along with some example logs. I am running the ESB 4.9.0 with the below proxy service for generate these sample logs. By default all these log files will be created at the location /repository/logs/ folder.

<?xml version="1.0" encoding="UTF-8"?>
<proxy xmlns="http://ws.apache.org/ns/synapse"
       name="TestProxy"
       transports="http,https"
       statistics="disable"
       trace="enable"
       startOnLoad="true">
   <target>
      <inSequence>
         <log level="custom">
            <property name="TEST" value="RECV"/>
         </log>
         <loopback/>
      </inSequence>
      <outSequence>
         <payloadFactory media-type="xml">
            <format>
               <test xmlns="">5</test>
            </format>
            <args/>
         </payloadFactory>
         <send/>
      </outSequence>
   </target>
   <description/>
</proxy>

WSO2 Carbon log

This is the main log file of the service and named as wso2carbon.log. It contains all the server level and service level logs. The default log level is INFO and it can be changed by changing below property in log4j.properties file to desired level.

log4j.logger.org.wso2.carbon=INFO

Trace log

It offers you a way to monitor a mediation execution and named as wso2-esb-trace.log. Trace logs will be enabled only if tracing is enabled on particular proxy or a sequence. If we enable tracing for the above proxy by using the management console we will get below.


13:54:03,490 [-] [PassThroughMessageProcessor-1]  INFO TRACE_LOGGER Proxy Service TestProxy received a new message from : 10.6.19.64
13:54:03,491 [-] [PassThroughMessageProcessor-1]  INFO TRACE_LOGGER Message To: /services/TestProxy.TestProxyHttpEndpoint/mediate
13:54:03,491 [-] [PassThroughMessageProcessor-1]  INFO TRACE_LOGGER SOAPAction: null
13:54:03,491 [-] [PassThroughMessageProcessor-1]  INFO TRACE_LOGGER WSA-Action: null
13:54:03,492 [-] [PassThroughMessageProcessor-1]  INFO TRACE_LOGGER Setting default fault-sequence for proxy
13:54:03,493 [-] [PassThroughMessageProcessor-1]  INFO TRACE_LOGGER Using the anonymous in-sequence of the proxy service for mediation
13:54:03,493 [-] [PassThroughMessageProcessor-1]  INFO TRACE_LOGGER Start : Sequence <anonymous>
13:54:03,494 [-] [PassThroughMessageProcessor-1]  INFO TRACE_LOGGER Sequence <SequenceMediator> :: mediate()
13:54:03,494 [-] [PassThroughMessageProcessor-1]  INFO TRACE_LOGGER Mediation started from mediator position : 0
13:54:03,494 [-] [PassThroughMessageProcessor-1]  INFO TRACE_LOGGER Start : Log mediator
13:54:03,496 [-] [PassThroughMessageProcessor-1]  INFO TRACE_LOGGER TEST = RECV
13:54:03,496 [-] [PassThroughMessageProcessor-1]  INFO TRACE_LOGGER End : Log mediator
13:54:03,496 [-] [PassThroughMessageProcessor-1]  INFO TRACE_LOGGER Start : Loopback Mediator
13:54:03,496 [-] [PassThroughMessageProcessor-1]  INFO TRACE_LOGGER Setting default fault-sequence for proxy
13:54:03,496 [-] [PassThroughMessageProcessor-1]  INFO TRACE_LOGGER Start : Sequence <anonymous>
13:54:03,496 [-] [PassThroughMessageProcessor-1]  INFO TRACE_LOGGER Sequence <SequenceMediator> :: mediate()
13:54:03,496 [-] [PassThroughMessageProcessor-1]  INFO TRACE_LOGGER Mediation started from mediator position : 0
13:54:03,496 [-] [PassThroughMessageProcessor-1]  INFO TRACE_LOGGER Building message. Sequence <SequenceMediator> is content aware
13:54:03,518 [-] [PassThroughMessageProcessor-1]  INFO TRACE_LOGGER Start : Send mediator
13:54:03,519 [-] [PassThroughMessageProcessor-1]  INFO TRACE_LOGGER Sending response message using implicit message properties..
Sending To: null
SOAPAction: null
13:54:03,529 [-] [PassThroughMessageProcessor-1]  INFO TRACE_LOGGER End : Send mediator
13:54:03,529 [-] [PassThroughMessageProcessor-1]  INFO TRACE_LOGGER End : Sequence <anonymous>
13:54:03,529 [-] [PassThroughMessageProcessor-1]  INFO TRACE_LOGGER End : Loopback Mediator
13:54:03,529 [-] [PassThroughMessageProcessor-1]  INFO TRACE_LOGGER End : Sequence <anonymous>
13:54:45,755 [-] [http-nio-9443-exec-18]  INFO TRACE_LOGGER Building Axis service for Proxy service : TestProxy
13:54:45,755 [-] [http-nio-9443-exec-18]  INFO TRACE_LOGGER Loading the WSDL :  <Inlined>
13:54:45,755 [-] [http-nio-9443-exec-18]  INFO TRACE_LOGGER Did not find a WSDL. Assuming a POX or Legacy service
13:54:45,755 [-] [http-nio-9443-exec-18]  INFO TRACE_LOGGER Exposing transports : [http, https]
13:54:45,757 [-] [http-nio-9443-exec-18]  INFO TRACE_LOGGER Adding service TestProxy to the Axis2 configuration
13:54:45,770 [-] [http-nio-9443-exec-18]  INFO TRACE_LOGGER Successfully created the Axis2 service for Proxy service : TestProxy

Patches log

All patch related logs are recorded in the Patches.log file. 

[2016-10-19 13:38:25,951]  INFO {org.wso2.carbon.server.util.PatchUtils} -  Checking for patch changes ...
[2016-10-19 13:38:25,953]  INFO {org.wso2.carbon.server.util.PatchUtils} -  New patch available - patch0049
[2016-10-19 13:38:25,957]  INFO {org.wso2.carbon.server.extensions.PatchInstaller} -  Patch changes detected 
[2016-10-19 13:38:31,949]  INFO {org.wso2.carbon.server.util.PatchUtils} -  Backed up plugins to patch0000
[2016-10-19 13:38:31,949]  INFO {org.wso2.carbon.server.util.PatchUtils} -  Applying patches ...
[2016-10-19 13:38:31,951]  INFO {org.wso2.carbon.server.util.PatchUtils} -  Applying - patch0049
[2016-10-19 13:38:31,966]  INFO {org.wso2.carbon.server.util.PatchUtils} -  Patched org.wso2.carbon.inbound.endpoint_4.4.10.jar(MD5:6f76773b9d10b200e8b7786a2787fc96)
[2016-10-19 13:38:31,996]  INFO {org.wso2.carbon.server.util.PatchUtils} -  Patched synapse-nhttp-transport_2.1.3-wso2v11.jar(MD5:907846d87999fbbc4ba8ac0381e97822)
[2016-10-19 13:38:31,997]  INFO {org.wso2.carbon.server.util.PatchUtils} -  Patch verification started
[2016-10-19 13:38:32,019]  INFO {org.wso2.carbon.server.util.PatchUtils} -  Patch verification successfully completed

Audit log

Audit logs provide information related to the users who has tried to access the server and do changes. It is recommended to enable audit logs in the production environment and it is named as audit.log.


[2016-10-19 13:44:43,522]  INFO -  'admin@carbon.super [-1234]' logged in at [2016-10-19 13:44:43,520-0500] 
[2016-10-19 13:45:14,190]  INFO -  'admin@carbon.super [-1234]' logged out at [2016-10-19 13:45:14,0188] 
[2016-10-19 13:46:14,976]  WARN -  Failed Administrator login attempt 'testuser[-1234]' at [2016-10-19 13:46:14,971-0500] 
[2016-10-19 13:47:49,084]  INFO -  'admin@carbon.super [-1234]' logged in at [2016-10-19 13:47:49,081-0500] 
[2016-10-19 13:48:29,501]  INFO -  Initiator : null@carbon.super | Action : Change Password by User | Target : null@carbon.super | Data : {  } | Result : Failed

Error log

All Errors and warnings at the server can be found in this log file named as wso2-esb-errors.log


2016-10-19 13:38:36,504 [-] [Start Level Event Dispatcher]  WARN ValidationResultPrinter Carbon is configured to use the default keystore (wso2carbon.jks). To maximize security when deploying to a production environment, configure a new keystore with a unique password in the production server profile.
2016-10-19 13:38:54,768 [-] [localhost-startStop-1]  WARN DefaultSchemaGenerator We don't support method overloading. Ignoring [validateAudienceRestriction]
2016-10-19 13:46:14,971 [-] [http-nio-9443-exec-32]  WARN CarbonAuthenticationUtil Failed Administrator login attempt 'tet[-1234]' at [2016-10-19 13:46:14,971-0500]
2016-10-19 13:48:29,515 [-] [http-nio-9443-exec-16] ERROR UserAdminClient Error while updating password. Wrong old credential provided 
org.wso2.carbon.user.mgt.stub.UserAdminUserAdminException: UserAdminUserAdminException
 at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
 at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
 at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
 at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
 at java.lang.Class.newInstance(Class.java:442)

ESB Service log

Informaton related to all service invocations information about called services etc and all logs that have been made with the "Log" Mediator in Synapse Proxies or Sequences can be found here.  By default INFO log level is used the file is named as wso2-esb-service.log

2016-10-19 14:50:09,209 [-] [localhost-startStop-1]  INFO TestProxy Building Axis service for Proxy service : TestProxy
2016-10-19 14:50:09,212 [-] [localhost-startStop-1]  INFO TestProxy Adding service TestProxy to the Axis2 configuration
2016-10-19 14:50:09,226 [-] [localhost-startStop-1]  INFO TestProxy Successfully created the Axis2 service for Proxy service : TestProxy
2016-10-19 14:55:06,491 [-] [PassThroughMessageProcessor-1]  INFO TestProxy TEST = RECV

Access Logs

Service and REST API invocation access log

tracks when a service or REST API is invoked. By default, the service/API invocation access logs are disabled for performance reasons. Can be enable by using below. The log file is created with the name as http_access_YYYY_MM_DD.log.

log4j.logger.org.apache.synapse.transport.http.access=INFO

If you invoke the service using below url we can see the logs as follows.



- fe80:0:0:0:d84a:683c:68a5:209%11 - - [19/Oct/2016:12:59:03 -0600] "GET /services/TestProxy.TestProxyHttpEndpoint/mediate HTTP/1.1" - - "-" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/53.0.2785.143 Safari/537.36"
- fe80:0:0:0:d84a:683c:68a5:209%11  - [19/Oct/2016:12:59:03 -0600] "- - " 200 - "-" "-"

Management Console Access Log

This tracks usage of the Management Console. By default it is created as http_access_management_console_YYYY_MM_DD.log file. It is rotated on a daily basis. To change the configurations of this log need to change below value in /repository/conf/tomcat/catalina-server.xml

<Valve className="org.apache.catalina.valves.AccessLogValve">


0:0:0:0:0:0:0:1 - - [19/Oct/2016:13:29:14 -0500] "GET /carbon/admin/js/jquery.ui.tabs.min.js HTTP/1.1" 200 3594 "https://localhost:9443/carbon/admin/login.jsp" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/53.0.2785.143 Safari/537.36"
0:0:0:0:0:0:0:1 - - [19/Oct/2016:13:29:14 -0500] "GET /carbon/admin/js/cookies.js HTTP/1.1" 200 1136 "https://localhost:9443/carbon/admin/login.jsp" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/53.0.2785.143 Safari/537.36"
0:0:0:0:0:0:0:1 - - [19/Oct/2016:13:29:14 -0500] "GET /carbon/admin/js/jquery.ui.core.min.js HTTP/1.1" 200 1996 "https://localhost:9443/carbon/admin/login.jsp" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/53.0.2785.143 Safari/537.36"

Trace Messages log

By default trace message logs are not enabled in the ESB. You can enable it for any required component by changing the log4j.properties file. For example trace for org.apache.synapse.transport.http.headers can be enabled by adding below. The logs will be created at wso2carbon-trace-messages.log file.

log4j.appender.CARBON_TRACE_LOGFILE=org.apache.log4j.DailyRollingFileAppender
log4j.appender.CARBON_TRACE_LOGFILE.File=${carbon.home}/repository/logs/${instance.log}/wso2carbon-trace-messages${instance.log}.log
log4j.appender.CARBON_TRACE_LOGFILE.Append=true
log4j.appender.CARBON_TRACE_LOGFILE.layout=org.wso2.carbon.utils.logging.TenantAwarePatternLayout
log4j.appender.CARBON_TRACE_LOGFILE.layout.ConversionPattern=[%d] %P%5p {%c} - %x %m %n
log4j.appender.CARBON_TRACE_LOGFILE.layout.TenantPattern=%U%@%D [%T] [%S]
log4j.appender.CARBON_TRACE_LOGFILE.threshold=TRACE
log4j.logger.org.apache.synapse.transport.http.headers=TRACE,CARBON_TRACE_LOGFILE

The generated log file contains below.

[2016-10-19 14:43:47,286] DEBUG {org.apache.synapse.transport.http.headers} -  http-incoming-1 >> POST /services/TestProxy.TestProxyHttpEndpoint/mediate HTTP/1.1 
[2016-10-19 14:43:47,288] DEBUG {org.apache.synapse.transport.http.headers} -  http-incoming-1 >> Content-Type: application/xml; charset=UTF-8 
[2016-10-19 14:43:47,289] DEBUG {org.apache.synapse.transport.http.headers} -  http-incoming-1 >> Cookie: region3_registry_menu=visible; region1_configure_menu=none; region4_monitor_menu=none; region5_tools_menu=none; MSG14769029100080.6387579241161663=true; menuPanel=visible; menuPanelType=main; requestedURI="../../carbon/service-mgt/index.jsp?region=region1&item=services_list_menu"; current-breadcrumb=manage_menu%2Cservices_menu%2Cservices_list_menu%23; JSESSIONID=9AEF469AF1960BA436D77E2B6F9BADEC 
[2016-10-19 14:43:47,297] DEBUG {org.apache.synapse.transport.http.headers} -  http-incoming-1 >> User-Agent: Axis2 
[2016-10-19 14:43:47,305] DEBUG {org.apache.synapse.transport.http.headers} -  http-incoming-1 >> Host: OMISLABL9:8280 
[2016-10-19 14:43:47,309] DEBUG {org.apache.synapse.transport.http.headers} -  http-incoming-1 >> Transfer-Encoding: chunked 
[2016-10-19 14:43:47,423] DEBUG {org.apache.synapse.transport.http.headers} -  http-incoming-1 << HTTP/1.1 200 OK 
[2016-10-19 14:43:47,424] DEBUG {org.apache.synapse.transport.http.headers} -  http-incoming-1 << Cookie: region3_registry_menu=visible; region1_configure_menu=none; region4_monitor_menu=none; region5_tools_menu=none; MSG14769029100080.6387579241161663=true; menuPanel=visible; menuPanelType=main; requestedURI="../../carbon/service-mgt/index.jsp?region=region1&item=services_list_menu"; current-breadcrumb=manage_menu%2Cservices_menu%2Cservices_list_menu%23; JSESSIONID=9AEF469AF1960BA436D77E2B6F9BADEC 
[2016-10-19 14:43:47,427] DEBUG {org.apache.synapse.transport.http.headers} -  http-incoming-1 << Host: OMISLABL9:8280 
[2016-10-19 14:43:47,434] DEBUG {org.apache.synapse.transport.http.headers} -  http-incoming-1 << Content-Type: application/xml; charset=UTF-8; charset=UTF-8 
[2016-10-19 14:43:47,440] DEBUG {org.apache.synapse.transport.http.headers} -  http-incoming-1 << Date: Wed, 19 Oct 2016 19:43:47 GMT 
[2016-10-19 14:43:47,446] DEBUG {org.apache.synapse.transport.http.headers} -  http-incoming-1 << Transfer-Encoding: chunked

Transaction logs

A transaction is a set of operations that executed as a single unit.WSO2 carbon platform has integrated the "Atomikos" transaction manager which is a implementation of Java Transaction API (JTA). Some products like WSO2DSS, WSO2ESB shipped this transaction manager by default. Then infomation related to Atomikos are logged in tm.out file.

INFO Start Level Event Dispatcher com.atomikos.logging.LoggerFactory - Using Slf4J for logging.
WARN Start Level Event Dispatcher com.atomikos.icatch.config.UserTransactionServiceImp - Using init file: /C:/Users/apathira/Desktop/WEST/Runtime/LOGGIN~1/WSO2ES~1.0/WSO2ES~1.0/bin/../lib/transactions.properties
INFO Start Level Event Dispatcher com.atomikos.persistence.imp.FileLogStream - Starting read of logfile C:\Users\apathira\Desktop\WEST\Runtime\LOGGIN~1\WSO2ES~1.0\WSO2ES~1.0\repository\data\tmlog12.log
INFO Start Level Event Dispatcher com.atomikos.persistence.imp.FileLogStream - Done read of logfile
INFO Start Level Event Dispatcher com.atomikos.persistence.imp.FileLogStream - Logfile closed: C:\Users\apathira\Desktop\WEST\Runtime\LOGGIN~1\WSO2ES~1.0\WSO2ES~1.0\repository\data\tmlog12.log
INFO Start Level Event Dispatcher com.atomikos.icatch.config.imp.AbstractUserTransactionService - USING core version: 3.8.0
INFO Start Level Event Dispatcher com.atomikos.icatch.config.imp.AbstractUserTransactionService - USING com.atomikos.icatch.console_file_name = tm.out
INFO Start Level Event Dispatcher com.atomikos.icatch.config.imp.AbstractUserTransactionService - USING com.atomikos.icatch.console_file_count = 1
INFO Start Level Event Dispatcher com.atomikos.icatch.config.imp.AbstractUserTransactionService - USING com.atomikos.icatch.automatic_resource_registration = true
INFO Start Level Event Dispatcher com.atomikos.icatch.config.imp.AbstractUserTransactionService - USING com.atomikos.icatch.client_demarcation = false
INFO Start Level Event Dispatcher com.atomikos.icatch.config.imp.AbstractUserTransactionService - USING com.atomikos.icatch.threaded_2pc = false
INFO Start Level Event Dispatcher com.atomikos.icatch.config.imp.AbstractUserTransactionService - USING com.atomikos.icatch.serial_jta_transactions = true
INFO Start Level Event Dispatcher com.atomikos.icatch.config.imp.AbstractUserTransactionService - USING com.atomikos.icatch.log_base_dir = repository/data
INFO Start Level Event Dispatcher com.atomikos.icatch.config.imp.AbstractUserTransactionService - USING com.atomikos.icatch.console_log_level = INFO
INFO Start Level Event Dispatcher com.atomikos.icatch.config.imp.AbstractUserTransactionService - USING com.atomikos.icatch.max_actives = 50
INFO Start Level Event Dispatcher com.atomikos.icatch.config.imp.AbstractUserTransactionService - USING com.atomikos.icatch.checkpoint_interval = 500
INFO Start Level Event Dispatcher com.atomikos.icatch.config.imp.AbstractUserTransactionService - USING com.atomikos.icatch.enable_logging = true
INFO Start Level Event Dispatcher com.atomikos.icatch.config.imp.AbstractUserTransactionService - USING com.atomikos.icatch.output_dir = repository/logs
INFO Start Level Event Dispatcher com.atomikos.icatch.config.imp.AbstractUserTransactionService - USING com.atomikos.icatch.log_base_name = tmlog
INFO Start Level Event Dispatcher com.atomikos.icatch.config.imp.AbstractUserTransactionService - USING com.atomikos.icatch.console_file_limit = 1073741824
INFO Start Level Event Dispatcher com.atomikos.icatch.config.imp.AbstractUserTransactionService - USING com.atomikos.icatch.max_timeout = 8000000
INFO Start Level Event Dispatcher com.atomikos.icatch.config.imp.AbstractUserTransactionService - USING com.atomikos.icatch.tm_unique_name = 10.6.19.64.tm
INFO Start Level Event Dispatcher com.atomikos.icatch.config.imp.AbstractUserTransactionService - USING java.naming.factory.initial = com.sun.jndi.rmi.registry.RegistryContextFactory
INFO Start Level Event Dispatcher com.atomikos.icatch.config.imp.AbstractUserTransactionService - USING java.naming.provider.url = rmi://localhost:1099
INFO Start Level Event Dispatcher com.atomikos.icatch.config.imp.AbstractUserTransactionService - USING com.atomikos.icatch.service = com.atomikos.icatch.standalone.UserTransactionServiceFactory
INFO Start Level Event Dispatcher com.atomikos.icatch.config.imp.AbstractUserTransactionService - USING com.atomikos.icatch.force_shutdown_on_vm_exit = true
INFO Start Level Event Dispatcher com.atomikos.icatch.config.imp.AbstractUserTransactionService - USING com.atomikos.icatch.default_jta_timeout = 5000000


Posted by at
Labels: ,

No comments:

Post a Comment

Subscribe to: Post Comments (Atom)