Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

W-11984725-logger-revamp-duke #2402

Open
wants to merge 15 commits into
base: v4.4
Choose a base branch
from
Open
Show file tree
Hide file tree
Changes from 3 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
211 changes: 178 additions & 33 deletions modules/ROOT/pages/logger-component-reference.adoc
Original file line number Diff line number Diff line change
Expand Up @@ -4,76 +4,221 @@ include::_attributes.adoc[]
endif::[]
:keywords: mule, esb, studio, logger, logs, log, notifications, errors, debug

This Core component helps you monitor and debug your Mule application by logging important information such as error messages, status notifications, payloads, and so on. You can add a Logger anywhere in a flow, and you can configure it to log a string that you specify, the output of a DataWeave expression you write, or any combination of strings and expressions.
Logs help you monitor and debug your Mule applications by printing important information such as error messages, status notifications, payload data, and so on. The Logger component (`<logger/>`) provides a way to add custom log messages to the logs. You can configure any number of Logger components in a flow to print a string, the output of a DataWeave expression, or any combination of strings and expressions.
dukesphere marked this conversation as resolved.
Show resolved Hide resolved

[WARNING]
--
Keep in mind that the Logger is one of the only components that supports mixing Strings and expressions within a value. DataWeave String interpolation or concatenation within a single expression should be used elsewhere.
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

moved to reference

--
Mule applications print logs in several locations. In Anypoint Studio, the logs print to the xref:studio::index.adoc#console[console]. For information about application logs in a production environment, see xref:logging-in-mule.adoc#app_logs[App Logs].

The configured messages are logged to the app's log file, which is located in `MULE_HOME/logs/<app-name>.log` if no custom log file path is specified in the `log4j2.xml` file. +
In Studio, the logs show in the Console.

The following example displays the message in Set Payload in a browser and also logs the message.
Copy link
Contributor Author

@dukesphere dukesphere Nov 11, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

removed bc "... in a browser": it's in the browser bc of the request to the listener, not directly relevant to logger

The following example logs the message `Hello MuleSoft!` at the default log level, `INFO`:

image::logger-flow.png[]

.Example: XML Configuration of the Flow
[source,xml,linenums]
----
<http:listener-config name="HTTP_Listener_Configuration" host="localhost" port="8081"/>
<flow name="logger-example-Flow">
<http:listener-config name="HTTP_Listener_config" doc:name="HTTP Listener config" >
<http:listener-connection host="0.0.0.0" port="8081" />
</http:listener-config><flow name="logger-example-Flow">
<http:listener config-ref="HTTP_Listener_Configuration" path="/"/>
<set-payload value="Hello MuleSoft!"/>
<logger message="#[payload]" level="INFO"/>
</flow>
----

== Logger Configuration
In the Studio console, the logged message, `Hello MuleSoft!` looks like this:

[source,logs]
----
INFO 2022-11-10 19:39:18,222 [[MuleRuntime].uber.01: [w-logger].logger-example-Flow.CPU_LITE @6f862394]
[processor: logger-example-Flow/processors/1; event: 6bd2b350-6172-11ed-9f87-147ddaaf4f97]
org.mule.runtime.core.internal.processor.LoggerMessageProcessor: Hello MuleSoft!
----

* The configurable log level is `INFO`. See <<reference>>.
* A date-time stamp `2022-11-10 19:39:18,222` marks an execution of a Logger.
* CPU_LITE is the See xref:execution-engine.adoc#processing_types[processing type].
* `event: 6bd2b350-6172-11ed-9f87-147ddaaf4f97` identifies the Mule event to which the logged message applies.
* The message `LoggerMessageProcessor` processor prints the message `Hello MuleSoft!`.

[[reference]]
== Reference

The Logger provides configurable properties for the name of the logger, the message to log, the log level, and a string you can use to name or categorize a type of log message.

image::logger.png[]

[%header%autowidth.spread,cols="a,a,a,a"]
[%header%autowidth.spread,cols="1a,1a,4a"]
|===
| Field | Value | Description | Example
| Field | Attribute | Description

| Message | String or DataWeave expression | Specifies the Mule log message. By default, messages are logged to the application's log file. |
`message="Current payload is #[payload]"`
| *Message* | `message` | String or DataWeave expression that specifies the Mule log message. By default, messages log to the application's log file. Example:
dukesphere marked this conversation as resolved.
Show resolved Hide resolved
`message="Current payload is \#[payload]"`. Note that the Logger is one of the only components that supports this syntax to embed an expression (such as `#[payload]` within a string. Messages in other Mule components require string interpolation or concatenation within a single DataWeave expression.

| Level |
Available options:
| Level | `level` | Specifies a log level. `INFO` is the default. Available options:

* `DEBUG`
* `ERROR`
* `INFO`(Default)
* `INFO`
* `TRACE`
* `WARN` |
Specifies the log level.

|
`level="ERROR"`
* `WARN`

| Category | String | Optional setting that specifies a category name that it adds to `log4j2.xml` file. For example, you might use a category to route your log messages based on your category, or you might set log levels based on category. |
`category="MyCustomCategory"`
Example: `level="ERROR"`

| Category | `category` | Optional string that specifies a category name that it adds to `log4j2.xml` file. For example, you might use a category to route your log messages based on your category, or you might set log levels based on category. Example:
`category="MyCustomCategory"`.
|===

== Examples

This Logger is set to monitor message processing status, mixing Strings and expressions:
The following example you specifies a category `category="MyCustomCategory"` with the `message="My Message"`:

[source,xml,linenums]
[source,xml]
----
<logger level="INFO" doc:name="Logger"
message='#["My Message"]' category="MyCustomCategory"/>
----

Notice that the category `MyCustomCategory` replaces the full package name of the processor, `org.mule.runtime.core.internal.processor.LoggerMessageProcessor`, for example:

[source,logs]
----
INFO 2022-11-11 15:17:53,138 [[MuleRuntime].uber.04:
[w-logger].logger-example-Flow.CPU_LITE @7ea85211]
[processor: logger-example-Flow/processors/1;
event: 113d6700-6217-11ed-86de-147ddaaf4f97]
MyCustomCategory: My Message
----

The following example places a DataWeave selector expression within a `message` string:

[source,xml]
----
<logger category="monitoring" message="Message #[payload.id] processed successfully" level="INFO"/>
----

This Logger set to record the processing time of a flow, using a single expression and DataWeave's String concatenation:
Assuming a payload such as `{"id" : "100", "some-key" : "some value" }`, the Logger prints the message `Message 100 processed successfully`, for example:

[source,xml,linenums]
[source,xml]
----
INFO 2022-11-10 21:11:07,791 [[MuleRuntime].uber.09:
[w-logger].logger-example-Flow.CPU_LITE @600dcddb]
[processor: logger-example-Flow/processors/1;
event: 3fd13710-617f-11ed-900f-147ddaaf4f97]
org.mule.runtime.core.internal.processor.LoggerMessageProcessor:
Message 100 processed successfully
----

This Logger records the processing time of a flow, using a single expression and DataWeave concatenation:

//TODO: Need to show how to get processing time or use a better example that doesn't throw an error.
[source,xml]
----
<logger category="performance" message="#['Message ' ++ payload.id ++ ' took ' ++ vars.processingTime ++ ' milliseconds to process']" level="INFO"/>
<logger category="performance" message="#['Message ' ++ payload.id ++ ' took ' ++ vars.processingTime ++ ' milliseconds to process']" level="INFO"/>
----

== See also
[[non_repeatable_streams]]
== Non-Repeatable Streams

In Mule, a non-repeatable stream can be read only once. Unlike most other Mule components, the Logger does not convert such a stream to a non-streamed or repeatable form.
dukesphere marked this conversation as resolved.
Show resolved Hide resolved

If a Logger receives a Mule event with a payload that is configured as a non-repeatable stream, the Logger consumes the payload, so the payload received by the next component in the flow returns `null`.
dukesphere marked this conversation as resolved.
Show resolved Hide resolved

This scenario can occur if a Mule components, such as as a xref:file-connector::file-documentation.adoc#write[File Write operation] or the xref:batch-reference.adoc#ref_batch_aggregator_component[Batch Aggregator] component, is configured with a _non-repeatable_ streaming strategy (see xref:tuning-repeatable-nonrepeatable.adoc[]).
dukesphere marked this conversation as resolved.
Show resolved Hide resolved

A component, such as Transform Message, converts such a payload into a non-streamed form. So a Logger located downstream of such a component no longer receives streamed payload.
dukesphere marked this conversation as resolved.
Show resolved Hide resolved

To illustrate this scenario, assume a Batch Aggregator that contains two Logger components is set to stream (`stream`) it input, the array `[1,2]`:
dukesphere marked this conversation as resolved.
Show resolved Hide resolved

[source,xml]
----
<flow name="streaming-to-logger-ex" >
<scheduler doc:name="Scheduler" >
<scheduling-strategy >
<fixed-frequency frequency="30" timeUnit="SECONDS"/>
</scheduling-strategy>
</scheduler>
<set-payload value="#[[1,2]]" doc:name="Set Payload" />
<batch:job jobName="Batch_Job">
<batch:process-records >
<batch:step name="Batch_Step" >
<batch:aggregator doc:name="Batch Aggregator"
streaming="true">
<!-- First Logger -->
<logger level="INFO" doc:name="Logger 1"
category="AGGREGATOR: FIRST LOGGER" message="#[payload as Array]" />
<!-- Transform Message 1 -->
<ee:transform doc:name="Transform Message">
<ee:message>
<ee:set-payload><![CDATA[%dw 2.0
output application/json
---
(payload)]]></ee:set-payload>
</ee:message>
</ee:transform>
<!-- Second Logger -->
<logger level="INFO" doc:name="Logger 2"
message="#[payload]"
category="AGGREGATOR: SECOND LOGGER" />
<!-- Transform Message -->
<ee:transform doc:name="Transform Message" >
<ee:message>
<ee:set-payload><![CDATA[%dw 2.0
output application/json
---
(payload + 100)]]></ee:set-payload>
</ee:message>
</ee:transform>
<!-- Third Logger -->
<logger level="INFO" doc:name="Logger 3"
message="#[payload]"
category="AGGREGATOR: THIRD LOGGER" />
</batch:aggregator>
</batch:step>
</batch:process-records>
</batch:job>
</flow>
----

* Logger 1, the first Logger component within the Aggregator, receives the array as a non-repeatable stream (`stream`), so it prints `[1, 2]` but passes an empty array `[]` to the next component in the Aggregator.
* The first Transform Message component receives the empty array from Logger 1 and sends it to Logger 2. So Logger 2 prints an _empty_ array (`[ ]`).
* The second Transform Message component appends `100` to the empty array, so Logger 3 prints the new payload, `[100]`.

The Loggers print the following (edited for readability):

[source,logs]
----
INFO ...AGGREGATOR: FIRST LOGGER: [1, 2]
INFO ...AGGREGATOR: SECOND LOGGER: [
]
INFO ... AGGREGATOR: THIRD LOGGER: [
100
]
----

Assume a scenario in which the first Transform Message component is located before the Logger 1. In this case, the Logger prints the following (edited):
dukesphere marked this conversation as resolved.
Show resolved Hide resolved

[source,logs]
----
INFO ...AGGREGATOR: FIRST LOGGER: [
1,
2
]
INFO ...AGGREGATOR: SECOND LOGGER: [
1,
2
]
INFO ... AGGREGATOR: THIRD LOGGER: [
1,
2
100
]
----

* Transform Message receives the streamed payload from the Aggregator but converts it to a non-streamed form. So the flow passes the unmodified array to Logger 1.
* Logger 1 prints the unmodified array in the payload, so it prints that array, `[1,2]`.
* The second Transform Message component appends `100` to the array, so Logger 3 prints the modified array, `[1,2,100]`.


== See Also

xref:dataweave::dataweave-types.adoc#dw_type_string[DataWeave String Type]
* xref:streaming-about.adoc[]
* xref:dataweave::dataweave-types.adoc#dw_type_string[DataWeave String Type]
6 changes: 3 additions & 3 deletions modules/ROOT/pages/logging-and-debugging.adoc
Original file line number Diff line number Diff line change
Expand Up @@ -9,10 +9,10 @@ Application logs and a runtime log help you monitor and troubleshoot your apps a

You can xref:enable-verbose-logging.adoc[enable verbose logging] for connectors and modules to record debug level information in the logs.

The Logger component can help you monitor or even debug your Mule app by logging important information such as error messages, status notifications, payloads, and so on. You can add a Logger anywhere in a flow, and you can configure it to log a string that you specify, the output of a DataWeave expression you write, or any combination of strings and expressions. For details, see xref:logger-component-reference.adoc[Logger Component] in the Core component documentation.
The Logger component can help you monitor and debug your Mule app by printing important information such as error messages, status notifications, payload data, and so on to a log file and the Anypoint Studio console. You can one or more Logger components to a flow, and you can configure it to print a string that you specify, the output of a DataWeave expression you write, or any combination of strings and expressions. For details, see xref:logger-component-reference.adoc[Logger Component] in the Core component documentation.

To control the display of Mule stack traces, you can use command-line arguments or set properties in Anypoint Studio. For details, see xref:configuring-mule-stacktraces.adoc[Configuring Mule Stack Traces].

To troubleshoot a Mule app in Anypoint Studio, you can use the xref:studio::visual-debugger-concept.adoc[Studio Visual Debugger], which lets you set breakpoints to stop execution and check events. If you are creating your Mule app outside of Studio, you can either use MUnit to test your app, or you can activate remote debugging. For details, see xref:debugging-outside-studio.adoc[Debugging Outside Studio].
To troubleshoot a Mule app in Anypoint Studio, you can use the xref:studio::visual-debugger-concept.adoc[Studio Visual Debugger], which lets you set breakpoints to stop execution and check events. If you are creating your Mule app outside of Studio, you can either use xref:munit::index.adoc[MUnit] to test your app, or you can activate remote debugging. For details, see xref:debugging-outside-studio.adoc[Debugging Outside Studio].

If you are running your Mule application in CloudHub, see xref:runtime-manager::viewing-log-data.adoc[View Log Data] for additional information about log data and persistence.
If you are running your Mule application in CloudHub, see xref:runtime-manager::viewing-log-data.adoc[View Log Data] for additional information about log data and persistence.
5 changes: 3 additions & 2 deletions modules/ROOT/pages/logging-in-mule.adoc
Original file line number Diff line number Diff line change
Expand Up @@ -4,13 +4,14 @@ include::_attributes.adoc[]
endif::[]
:keywords: mule, studio, logger, logs, log, notifications, errors, debug

MuleSoft provides application logs and a runtime log to help you monitor and troubleshoot your Mule applications and the Mule instance.
MuleSoft provides application logs and a runtime log to help you monitor and troubleshoot your Mule applications and the Mule Runtime engine instance.

[[app_logs]]
== App Logs

Every app that you build in Studio comes with its own `log4j2.xml` file. The log contains information about any errors raised in the app (unless you have app logic to handle those errors). It also contains anything you want to explicitly log, if you build the logic in the app.

Mule automatically logs multiple messages and specific elements in your app flows to help you debug and keep track of events. You can also include the xref:logger-component-reference.adoc[Logger component] anywhere in a flow and set it up to output any message you want.
Mule automatically logs multiple messages and specific elements in your app flows to help you debug and keep track of events. You can also configure any number of xref:logger-component-reference.adoc[Logger components] in the flow to print log messages that you want.

You can view an app log as follows:

Expand Down