{section}
{column}

h1. Logging systems

Petals ESB uses the logging system provided by the JDK.

The logger configuration is determined according to the following ordered rules:
# the file defined as value of the Java system property {{petals.container.log.config.file}} (set on the Java command line through the environment file, ie. {{env.sh|bat}}),
# the file defined as value of the property {{petals.container.log.config.file}} of the local container configuration, ie. {{server.properties}},
# the file '{{loggers.properties}}' located in the same path than the local container configuration, ie. {{server.properties}}.

Each property value of the JDK logging system configuration file can contain reference to other properties using a placeholder as:
{code}org.ow2.petals.log.handler.PetalsFileHandler.basedir=${petals.log.dir}{code}
Available properties to use as placeholder are:
* the system properties including all properties defined on the java command line using the flag '{{-D}}',
* the properties of the container configuration file, ie. {{server.properties}}.

{tip}Think to use the environment file, ie. {{env.sh|bat}}, instead of updating the Petals startup script to set your system properties.{tip}

{column}
{column:width=350px}
{panel:title=Table of contents}{toc:outline=true}{panel}
{panel:title=Contributors}{contributors:order=name|mode=list|showAnonymous=true|showCount=true|showLastTime=true}{panel}
{column}
{section}

h1. Petals Logging specificities

{tip}You can find more informations about few concepts mentioned below in [glossary|Glossary].{tip}

h2. Log levels

Petals defines a new specific level: MONIT. This level is used to [trace the process activities and permit to deduce the process execution launched by an initial request|Monitoring processes with their logs].

The level MONIT is inserted between levels CONFIG and FINE:
* SEVERE (highest value): An error occurs when the service can not be provided:
** In a Petals ESB container point of view, an error is something that stops the processing of an internal component. Consequently, the Petals ESB is stopped because it can assume its functions,
** In a component (BC/SE) point of view, an error is something that stops the processing of the SE or BC, but other components are always running correctly. Consequently, the component could be stopped,
** In a service (service-unit) point of view, an error is something that stops the processing of a service, each service invocation will fail, but other services deployed on the same component are correctly running. Consequently, the service could be stopped,
* WARNING: A warning occurs when the service is partially provided and is compensated by a default behavior or it could be hot-fixed without restart or re-installation,
* INFO: The information level highlights the provided service. Such a trace is logged parsimoniously. For example, service life cycle states are logged with this level,
* CONFIG: All parameter values are logged with this level,
* *MONIT*: This level is used to trace incoming and outgoing service messages to be able [to monitor process executions in a business point of view|Monitoring processes with their logs],
* FINE: All traces that can help a problem analysis are logged with this level.
* FINER: All traces that can help a problem analysis are logged with this level.
* FINEST (lowest value) : All traces that can help a problem analysis are logged with this level.

According to the log level of the logger, the debug traces generated with log level {{FINE}}, {{FINER}} and {{FINEST}} can be extended with class and method name where the trace occurs:
* FINE:
** all traces except *debug* traces are printed *without* class and method name,
** the *debug* traces are printed *without* class and method name, and *no method entrance traces* 'start'/'end'/'call' are generated,
* FINER:
** all traces except *info* and *debug* traces are printed *without* class and method name,
** the *info* and *debug* traces are printed *with* class and method name, and *no method entrance traces* 'start'/'end'/'call' are generated,
* FINEST:
** all traces except *info* and *debug* traces are printed *without* class and method name,
** *info* traces, *debug* traces and *method entrance traces* 'start'/'end'/'call' are printed *with* class and method name.

The new level {{MONIT}} comes with dedicated information. So, to be printed, a new formatter was created: [{{org.ow2.petals.log.formatter.LogDataFormatter}}|#petals_formatter]. This formatter can be used with standard handlers as {{java.util.logging.ConsoleHandler}}.

To trace exchange activities into files, it is better to have a policy based on one log file per process instance instead of having one big file. One file by process instance is more human readable. So a new file handler is also provided: [{{org.ow2.petals.log.handler.PetalsFileHandler}}|#petals_file_handler].

The MONIT level permits also to dump the message exchange content using another dedicated file handlers:
* [{{org.ow2.petals.log.handler.PetalsPayloadDumperFileHandler}}|#petals_dumper_file_handler]. It is based on the file handler '{{org.ow2.petals.log.handler.PetalsFileHandler}}' adding it capabilities to dump the payload IN, OUT or fault of message exchanges,
* [{{org.ow2.petals.log.handler.PetalsExchangeDumperFileHandler}}|#petals_dumper_file_handler]. It is based on the file handler '{{org.ow2.petals.log.handler.PetalsFileHandler}}' adding it capabilities to dump message exchanges completely:
** message exchange info: id, interface, service, endpoint, operation, pattern, status,
** message exchange properties,
** normalized messages:
*** properties,
*** content,
*** attachments,
** fault,
** error.

h2. Default levels

The default root logger level is WARNING. It means that all classes log only SEVERE and WARNING information.

The default Petals root logger level is INFO. That's why all Petals components will log only SEVERE, WARNING and INFO information.

The default components level is MONIT.

You can enable logging and specify a specific level for each module (container, component, cdk...). Here is how you would set debugging from Petals. You would need to ensure the Handler's level is also set to collect this threshold, so FINEST or ALL should be set.
{code}
##Petals level
Petals.level = FINEST

#Handler Configuration
java.util.logging.ConsoleHandler.level = FINEST
{code}

Example of configuration to debug (Level FINEST) petals-bc-soap component:
{code}
##Petals level
Petals.level = INFO #Log level for all petals services
Petals.Container.Components.level = MONIT #log level for all components
Petals.Container.Components.petals-bc-soap.level = FINEST #Log level for petals-bc-soap component

#Handler Configuration
java.util.logging.ConsoleHandler.level = FINEST
{code}

{anchor:petals_formatter}
h2. Petals formatter

The Petals formatter {{org.ow2.petals.log.formatter.LogDataFormatter}} is used for both standard traces of the Petals ESB container and process activity traces. The format of the logged message is :
{panel:borderStyle=solid}+Petals Node Name+ +YYYY/MM/DD+ +HH:MM:SS,FFF+ +GMT+ +LOG LEVEL+ \[+LOGGER NAME+] : +LOG MESSAGE+{panel}
For a process activity, the log message is composed of several fields as key/value depending on the JBI component and activity. See [Monitoring processes with their logs] for more information on fields.

*Example of logging output with the Petals formatter:*
{code}
sample-0 2013/03/07 10:31:31,084 GMT+0100 INFO [Petals.Communication.RMIConnector] : JMX RMI server started at : service:jmx:rmi:///jndi/rmi://localhost:7700/jmxRmiConnector
...
sample-0 2013/03/07 10:31:32,459 GMT+0100 MONIT [Petals.Container.Components.petals-bc-soap] : traceCode = 'consumeFlowStepBegin',flowInstanceId = '62cdea40-cf20-11e0-bdfa-000c29523cc7',flowStepId = '62ce3860-cf20-11e0-bdfa-000c29523cc7',flowInterfaceName = '{[http://usecase1/bpel-P12/]}interfaceName1',flowServiceName = '{[http://usecase1/bpel-P12/]}serviceName1',flowEndpointName = 'endpointName1',flowOperationName = '{[http://usecase1/bpel-P12/]}process',client = '192.168.1.157',requestedURL = 'http://192.168.1.196:8084/petals/services/soap-C1'
{code}

{tip}
It is possible to change the format of the logs using a pattern as with Java's {{SimpleFormatter}}. See the {{loggers.properties}} file for details.
{tip}

{anchor:petals_file_handler}
h2. Splitting log files

Petals ESB allow to split its log records into a log files hierarchy. Thanks to the Petals file handler '{{org.ow2.petals.log.handler.PetalsFileHandler}}' which can redirect log records to separate files according to their nature:
* if the log record is generated into a process activity context, it is redirected in the log file dedicated to the process instance,
* otherwise, the log record is sent into the global log file.

{anchor:log_file_hierarchy}
The default log files hierarchy is the following one:
* basedir
** petals.log: The global log file in which log records that are not generated into a process activity context are logged,
** flow-monitoring: Directory in which log files of log records associated to process activities are written,
*** <uid>: Directory of log files associated to the activities of only *ONE* process instance,
**** petals.log: The log file of process activities of only *ONE* process instance.

In addition to the standard properties ({{level}} and {{formatter}}), the specific configuration properties of the Petals file handler are:
|| Property || Default value || Description ||
| {{xxx.basedir}} | The value of the system property '{{petals.log.dir}}'. | The root directory of the log file hierarchy. If the value is a relative path, it will be relative to the working directory from where Petals is executed. |
| {{xxx.flows-subdir}} | {{flow-monitoring}} | The name of the directory contained in the directory {{basedir}} where log files of log records associated to process activities are written. If the value is a relative, it will be relative to the base directory. Absolute value is accepted. |
| {{xxx.logFilename}} | {{petals.log}} | The name of log files. It's a relative filename value, without directory |
where {{xxx}} is the name of the log handler: {{org.ow2.petals.log.handler.PetalsFileHandler}}, {{org.ow2.petals.log.handler.PetalsPayloadDumperFileHandler}} or {{org.ow2.petals.log.handler.PetalsExchangeDumperFileHandler}}.

{tip}The Petals file handler processes all log record according to their log level and its own log level. So split files can be generated containing only traces with log level SEVERE, WARNING or INFO when the min log level is set to INFO. To have *no splitted files* (ie. no traces about process execution), you must *disable the Petals log handler*, and add the default log file handler of the JDK logging system {{java.util.logging.FileHandler}} to retain a global log file:
{code}
handlers=java.util.logging.ConsoleHandler, java.util.logging.FileHandler

java.util.logging.ConsoleHandler.level=FINEST
java.util.logging.ConsoleHandler.formatter=org.ow2.petals.log.formatter.LogDataFormatter

java.util.logging.FileHandler.level=FINEST
java.util.logging.FileHandler.pattern=%h/petals-esb-enterprise-edition/petals-esb/logs/petals.log
java.util.logging.FileHandler.formatter=org.ow2.petals.log.formatter.LogDataFormatter

...

{code}
{tip}

{anchor:petals_dumper_file_handler}
h2. Debugging process execution

In the previous paragraph, you see how to get traces about process instance executions. For a debugging or replaying purpose, it is interesting to get the content of messages exchanged. This is possible using another Petals file log handlers: {{org.ow2.petals.log.handler.PetalsPayloadDumperFileHandler}} and {{org.ow2.petals.log.handler.PetalsExchangeDumperFileHandler}} based on the previous file log handler {{org.ow2.petals.log.handler.PetalsFileHandler}}.

The content of the messages are dumped in the log files hierarchy defined [above|#log_file_hierarchy] in the directory dedicated to the current process instance. One dump file is created for each message sent or received. The content of dump depends on the petals log handler. The path of the dump file is logged, if possible as a relative path to {{basedir}}, in the MONIT trace through a dedicated field: {{dumpFile}}.

In order to dump message, this log handler needs to maintain a pool of object helping it to transform in-memory XML representation of the payload to text.

| {{xxx.transformersPoolMaxActive}} | The default value is 8 | The maximum number of objects available to dump a message at a given moment: limit the the number of concurrent dump to disk. |
| {{xxx.transformersPoolMaxIdle}} | The default value is 8 | The maximum number of objects available and not used at a given moment: will trigger freeing of memory when exceeded. |
where {{xxx}} is the name of the log handler: {{org.ow2.petals.log.handler.PetalsPayloadDumperFileHandler}} or {{org.ow2.petals.log.handler.PetalsExchangeDumperFileHandler}}.

{note}An issue JIRA already exists to dump the whole content of messages, including properties and attachments: {jira:PETALSESBCONT-228}{note}

h2. Disabling log file hierarchy

By default, the Petals ESB configuration uses the log handler {{org.ow2.petals.log.handler.PetalsFileHandler}} that manages a log files hierarchy. If you don't use log trace MONIT, you have always this file hierarchy that could contains warning or severe errors. In some case, you will prefer to have only one global log file instead of this hierarchy to avoid a potential huge number of files. Simply replace the log handler {{org.ow2.petals.log.handler.PetalsFileHandler}} by, for example, {{java.util.logging.FileHandler}}:
{code}
# Configuration of the log handlers
#####################################
handlers=java.util.logging.ConsoleHandler, java.util.logging.FileHandler

# Configuration of the handler FileHandler
##################################################
java.util.logging.FileHandler.level=CONFIG
java.util.logging.FileHandler.pattern=/var/log/petals/petals%u-%g.log
java.util.logging.FileHandler.limit=50000
java.util.logging.FileHandler.count=10
java.util.logging.FileHandler.formatter=org.ow2.petals.log.formatter.LogDataFormatter
{code}

{tip}
To be able to print correctly MONIT traces, you must use the formatter {{org.ow2.petals.log.formatter.LogDataFormatter}}
{tip}

h2. Performances

Performances decrease when activating MONIT log level, and mainly if the log handlers {{org.ow2.petals.log.handler.PetalsPayloadDumperFileHandler}} or {{org.ow2.petals.log.handler.PetalsExchangeDumperFileHandler}} are enabled. To reduce the performance impact, you can apply an asynchronous pattern, for example using the log handler {{java.util.logging.MemoryHandler}} linked to {{org.ow2.petals.log.handler.PetalsFileHandler}}:
{code}
handlers=java.util.logging.ConsoleHandler, java.util.logging.MemoryHandler

java.util.logging.MemoryHandler.level=FINEST
java.util.logging.MemoryHandler.size=1000
java.util.logging.MemoryHandler.target=org.ow2.petals.log.handler.PetalsFileHandler
{code}

h2. Using your own log handler

Since the version 4.2 of Petals ESB, custom log handlers are supported. See the [source project code of Petals provided log handlers|https://anonymous:anonymous@svn.petalslink.org/svnroot/trunk/product/dev/prod/petals/tools-commons/petals-log] to write your own.

If you want to redirect the MONIT traces elsewhere than into log files, you can use your own log handler. Just put its JAR file and dependencies into the Petals system-extensions directory, and configure your log handler into the logging configuration file.

h1. Tuning your logging configuration

h2. How to set the log level of components separately

Each binding component instance or service engine instance have its own logger that you can configure separately. The logger name has the following pattern: {{Petals.Container.Components.<component-jbi-identifier>}}, where {{<component-jbi-identifier>}} is the unique identifier of the component that you can find in its JBI descriptor.

With the following configuration, all components installed will log with a {{MONIT}} level, except the BC SOAP '{{petals-bc-soap}}' and the BC SQL '{{petals-bc-sql-1}}' that uses the level {{INFO}}. The second BC SQL '{{petals-bc-sql-2}}' will use the level {{FINE}}:
{code}
...
Petals.Container.Components.level=MONIT
Petals.Container.Components.petals-bc-soap.level=INFO
Petals.Container.Components.petals-bc-sql-1.level=INFO
Petals.Container.Components.petals-bc-sql-2.level=FINE
...
{code}

h2. Petals ESB automatically started on Debian-based system

If your Petals ESB containers used in production are:
* installed on Debian-based systems through Debian packages,
* and, running in [automatic mode|Starting and stopping Petals ESB installed by Debian packages],

you can disable the log handler 'console' for which all generated traces on the standard output are discarded, and used only a log handler 'file' ({{java.util.logging.FileHandler}}, {{org.ow2.petals.log.handler.PetalsFileHandler}}, {{org.ow2.petals.log.handler.PetalsPayloadDumperFileHandler}} or {{org.ow2.petals.log.handler.PetalsExchangeDumperFileHandler}} according to your needs about the [flow monitoring|Monitoring processes with their logs]).
{code}
# Configuration of the log handlers
#####################################
#handlers=java.util.logging.ConsoleHandler, org.ow2.petals.log.handler.PetalsFileHandler
handlers=org.ow2.petals.log.handler.PetalsFileHandler
{code}

h2. Petals ESB manually started or installed through ZIP archive
If your Petals ESB installation does not satisfy the previous criteria (not running in automatic mode on a Debian-based system), you can improve performance decreasing the level of the log handler 'console':
{code}
# Configuration of the handler ConsoleHandler
##################################################
java.util.logging.ConsoleHandler.level=INFO
java.util.logging.ConsoleHandler.formatter=org.ow2.petals.log.formatter.LogDataFormatter
{code}
You can also remove the log handler 'console' but it's disturbing because no more trace will be printed.

h1. Known problems

h2. No trace more precise than INFO level are logged in the log file

*Operating system:* Debian-based Linux

*Symptoms:*
* Petals ESB is installed with the Debian packages,
* A Petals ESB container is started through the [automatic startup|Starting and stopping Petals ESB installed by Debian packages] ({{sudo service petals-esb start}}), or when booting the host,
* The log configuration file defines level FINEST for JBI component, or equivalent,
* No trace with level FINEST are flushed in the global log file ({{/var/log/petals-esb/<container-name>/petals.log}})

*Solutions to try:*
* Change the log level of the log handler {{org.ow2.petals.log.handler.PetalsFileHandler}}, {{org.ow2.petals.log.handler.PetalsPayloadDumperFileHandler}} or {{org.ow2.petals.log.handler.PetalsExchangeDumperFileHandler}} and set it the value FINEST.

*Explanations:*
By default, the log configuration set a log level FINEST to the log handler 'console', and the standard output of Petals ESB container is redirected to {{/dev/null}} by the SysV init.
The global log file is the file generated by the log handler {{org.ow2.petals.log.handler.PetalsFileHandler}}, {{org.ow2.petals.log.handler.PetalsPayloadDumperFileHandler}} or {{org.ow2.petals.log.handler.PetalsExchangeDumperFileHandler}}.