Logging and Correlation in message mediation

Why message logging is important?

When developing the enterprise applications, the logging is the important practice to identify the security threats, errors and usage patterns of the systems. When talk about the message logging relevant to the integration and the message mediation, It is important to debug the issues in both in and out flows of the mediation including the behaviours of external endpoint invocations in service orchestration.

WSO2 log mediator

WSO2 log mediator is used to log the message in the mediation flow. It supports for different log levels and log categories. Log mediator is conditional content aware. That means building the message by log mediator in the mediation flow is depend on the selected log level.

Syntax:
<log [level=”string”] [separator=”string”]> <property name=”string” (value=”literal” | expression=”[XPath|json-eval(JSON Path)]”)/>* </log>

What are the different log levels of log mediator?

What are the different log categories of log mediator?

• Full: If this is selected, all the standard headers logged at the Simple level as well as the full payload of the message will be logged. This log level causes the message content to be parsed and hence incurs a performance overhead.
• Simple: If this is selected, the standard headers (i.e. To, From, WSAction, SOAPAction, ReplyTo, and MessageID) will be logged.
• Headers: If this is selected, all the SOAP header blocks are logged.
• Custom: If this is selected, only the properties added to the Log mediator configuration will be logged.

Whitepaper Microservices for the Enterprise

Take your business to the next level with microservices

Download now

Important points need to be considered in message logging

• Message correlation id

Message correlation Id is a unique Id allocated to the incoming HTTP request. The same Id is maintaining all in and out flows of the particular request in mediation flow. All the log entries can refer the correlation Id to clearly identify the round trip of the HTTP request and It would be helpful to analyze the behaviour of the message flow and debug the message mediation.

Note:
When HTTP request received by the gateway node of the connext platform, It will generate a correlation Id and set it to the HTTP header “correlationId”,  before sending it to the backend.

• Minimize the logging

We always trying to minimise the message logging since it is directly impacting to the performance of the system. Writing log into the file is a I/O operation and use some considerable resources from the system.

Note:
The ELK stack has already been setup with the connext platform for the monitoring and logging purposes. The connext 2.3 has defined the maximum number of characters per INFO and DEBUG log line in the service log.

INFOLOGS- 1024 characters

appender.INFOLOGS.layout.pattern = [CNXT2][%d] %5p %.-1024m {INFOLOGS}%n

DEBUGLOGS- 1048576 characters

appender.DEBUGLOGS.layout.pattern = [CNXT2][%d] %5p %.-1048576m {DEBUGLOGS}%n

This limitation is set to run the ELK system smoothly with the existing resource allocation and minimize the I/O cost of the integration system.

• Order of the log level

The heart of the wso2 logging is based on log4j2 and same ordering mechanism is applicable

DEBUG < INFO < WARN < ERROR < FATAL < OFF

Example: If INFO logs are enabled in the log4j2.properties, then all log levels are logged other than DEBUG level.

• Logger templates

To minimize the redundancy, we can define a sequence template as a common logger template to reuse it whenever you want by passing the values for the relevant parameter. The ‘sequence template’ can be called from the ‘call template’

Syntax: sequence template

<?xml version=”1.0″ encoding=”UTF-8″?> <template name=”string”> <!– parameters this sequence template will be supporting –> ( <parameter name=”string” /> ) * <!–this is the in-line sequence of the template –> <sequence>mediator+</sequence> </template>

Syntax: call template

<?xml version=”1.0″ encoding=”UTF-8″?> <call-template target=”string”> <!– parameter values will be passed on to a sequence template –> ( <!–passing plain static values –> <with-param name=”string” value=”string” /> | <!–passing xpath expressions –> <with-param name=”string” value=”{string}” /> | <!–passing dynamic xpath expressions where values will be compiled dynamically–> <with-param name=”string” value=”{{string}}” /> | ) * <!–this is the in-line sequence of the template –> </call-template>

• Minimize the payload logging

In some situations, we will have to log the payload for the debugging purposes. But It is not good to log the payload other than DEBUG log level. One reason is the cost of logging I/O operation. The other reason is in production system, the payload carries lot of sensitive information and not a best practice to always log the payload.

In debugging process, the major reason to log the payload is to detect the problems with the data contains in the payload. But without logging the payload, we can use the validation step to validate the data in the various levels of mediation.

1. HTTP Request validation
2. Validation after the payload enhancement or transformation (enriching mediator, xslt mediator etc…)
3. Validation in/out service orchestration
4. HTTP Response validation

WSO2 has introduced the validator mediator to validate the xml or json payloads against the predefined validation schema.

Syntax:

<validate [source=”xpath”]> <property name=”validation-feature-id” value=”true|false”/>* <schema key=”string”/>+ <on-fail> mediator+ </on-fail> </validate>

The following diagram illustrate the different levels of payload validation in mediation flow.

Integration sample to validate the payload in the mediation flow

Step 1:
Create an API in publisher by the following API definition

openapi: 3.0.1

info:

title: Logger_Test_Api

version: '1.0'

servers:

- url: /

security:

- default: []

paths:

/*:

get:

responses:

'200':

description: OK

security:

- default: []

x-auth-type: Application & Application User

x-throttling-tier: Unlimited

put:

responses:

'200':

description: OK

security:

- default: []

x-auth-type: Application & Application User

x-throttling-tier: Unlimited

post:

responses:

'200':

description: OK

security:

- default: []

x-auth-type: Application & Application User

x-throttling-tier: Unlimited

delete:

responses:

'200':

description: OK

security:

- default: []

x-auth-type: Application & Application User

x-throttling-tier: Unlimited

patch:

responses:

'200':

description: OK

security:

- default: []

x-auth-type: Application & Application User

x-throttling-tier: Unlimited

/employee:

post:

parameters: []

requestBody:

content:

application/xml:

schema:

type: object

required: false

responses:

'200':

description: ok

security:

- default: []

x-auth-type: None

components:

securitySchemes:

default:

type: oauth2

flows:

implicit:

authorizationUrl: 'https://test.com'

scopes: {}

x-wso2-auth-header: Authorization

x-throttling-tier: Unlimited

x-wso2-cors:

corsConfigurationEnabled: false

accessControlAllowOrigins:

- '*'

accessControlAllowCredentials: false

accessControlAllowHeaders:

- authorization

- Access-Control-Allow-Origin

- Content-Type

- SOAPAction

accessControlAllowMethods:

- GET

- PUT

- POST

- DELETE

- PATCH

- OPTIONS

x-wso2-production-endpoints:

urls:

- 'https://internal-esb.prod.yenlo.connext.com:8243/yenlo'

type: http

x-wso2-sandbox-endpoints:

urls:

- 'https://internal-esb.prod.yenlo.connext.com:8243/yenlo'

type: http

x-wso2-basePath: /logger_test/1.0

x-wso2-transports:

- http

- https

• The API resource which we have exposed from gateway https://<Gatewayhost>/logger_test/1.0/employee
• The production endpoint is an API creted in the WSO2 EI

https://:8243/yenlo

Step 2:
Create the following API in WSO2 EI. This is the one we have pointed as a production endpoint ofthe API exposed in gateway.

<api xmlns="http://ws.apache.org/ns/synapse" name="Test_Api" context="/yenlo">

<resource methods="POST" uri-template="/employee">

<inSequence>

<call-template target="Logger_Template">

<with-param name="SequenceName" value="Test_Api"/>

<with-param name="Message" value="Request received by the API"/>

<with-param name="LogCategory" value="INFO"/>

</call-template>

<sequence key="gov:/MessageTransformationSequence"/>

<respond/>

</inSequence>

</resource>

</api>

Step 3:
Create the below mediation sequence and saved in the registry

<?xml version="1.0" encoding="UTF-8"?><sequence xmlns="http://ws.apache.org/ns/synapse">

<call-template target="Logger_Template">

<with-param name="SequenceName" value="MessageTransformationSequence"/>

<with-param name="Message" value="Started"/>

<with-param name="LogCategory" value="INFO"/>

</call-template>

<validate>

<schema key="gov:/schemas/RequestValidator.xsd"/>

<on-fail>

<call-template target="Logger_Template">

<with-param name="SequenceName" value="MessageTransformationSequence"/>

<with-param name="Message" value="Invalid request received"/>

<with-param name="LogCategory" value="ERROR"/>

</call-template>

<makefault version="soap12">

<code value="tns:Receiver" xmlns:tns="http://www.w3.org/2003/05/soap-envelope"/>

<reason value="Invalid Request received!!!"/>

</makefault>

<property name="HTTP_SC" scope="axis2" value="400"/>

<respond/>

</on-fail>

</validate>

<property name="ContentType" scope="axis2" value="application/json"/>

<payloadFactory media-type="json">

<format>{ "employeeName": "$1", "company": "$2", "mobileNumber": "$3", "department": "engineering" }</format>

<args>

<arg evaluator="json" expression="$.employee.firstName" literal="false"/>

<arg evaluator="json" expression="$.employee.company" literal="false"/>

<arg evaluator="json" expression="$.employee.mobileNumber" literal="false"/>

</args>

</payloadFactory>

<property name="ContentType" scope="axis2" value="application/json"/>

<validate>

<schema key="gov:/schemas/TransformationValidator.json"/>

<on-fail>

<call-template target="Logger_Template">

<with-param name="SequenceName" value="MessageTransformationSequence"/>

<with-param name="Message" value="Failed to validate the payload after transformation"/>

<with-param name="LogCategory" value="ERROR"/>

</call-template>

<makefault version="soap12">

<code value="tns:Receiver" xmlns:tns="http://www.w3.org/2003/05/soap-envelope"/>

<reason value="Failed in message transformation!!!"/>

</makefault>

<property name="HTTP_SC" scope="axis2" value="500"/>

<respond/>

</on-fail>

</validate>

<property name="messageType" scope="axis2" value="application/json"/>

<call-template target="Logger_Template">

<with-param name="SequenceName" value="MessageTransformationSequence"/>

<with-param name="Message" value="Cmpleted"/>

<with-param name="LogCategory" value="INFO"/>

</call-template>

<respond/>

</sequence>

The sequence logic is actually doing the validation in two different stages.

Once the request received, the first validate mediation do the request validation against the RequestValidator.xsd

The second validate mediator do the payload validation after the message transformation by payload factory mediator against the TransformationValidator.json

Step 4:
Create below logger template to reuse in the mediation logging flow

<?xml version="1.0" encoding="UTF-8"?><template xmlns="http://ws.apache.org/ns/synapse" name="Logger_Template">

<parameter name="SequenceName"/>

<parameter name="Message"/>

<parameter name="LogCategory"/>

<sequence>

<switch source="$func:LogCategory" xmlns:ns="http://org.apache.synapse/xsd" xmlns:ns2="http://org.apache.synapse/xsd">

<case regex="Error|ERROR|error">

<log category="ERROR" level="custom">

<property expression="$ctx:proxy.name" name="ServiceName"/>

<property expression="$func:SequenceName" name="SequenceName"/>

<property expression="$trp:correlationId" name="Correlation-Id"/>

<property expression="$ctx:ERROR_CODE" name="ERROR_CODE"/>

<property expression="$axis2:HTTP_SC" name="HTTP_CODE"/>

<property expression="$func:Message" name="Message"/>

<property expression="$ctx:ERROR_MESSAGE" name="ERROR_MESSAGE"/>

<property expression="$ctx:ERROR_DETAIL" name="ERROR_DETAIL"/>

<property expression="$ctx:ERROR_EXCEPTION" name="ERROR_EXCEPTION"/>

</log>

<log category="DEBUG" level="custom">

<property expression="$func:SequenceName" name="SequenceName"/>

<property expression="$trp:correlationId" name="Correlation-Id"/>

<property expression="$body" name="MessageBody"/>

</log>

</case>

<default>

<log level="custom">

<property expression="$func:SequenceName" name="SequenceName"/>

<property expression="$trp:correlationId" name="Correlation-Id"/>

<property expression="$axis2:HTTP_SC" name="HTTP_CODE"/>

<property expression="$func:Message" name="Message"/>

</log>

<log category="DEBUG" level="custom">

<property expression="$func:SequenceName" name="SequenceName"/>

<property expression="$trp:correlationId" name="Correlation-Id"/>

<property expression="$axis2:HTTP_SC" name="HTTP_CODE"/>

<property expression="$body" name="MessageBody"/>

</log>

</default>

</switch>

</sequence>

</template>

Here you can see, we have added the payload logging under DEBUG log level. If we have enabled the DEBUG logs for the particular service, then only we can have the debug logs with the payload logging.

Step 5:
Create following validation schemas and save in registry.

Xml validation schema

<?xml version="1.0" encoding="utf-8"?>

<xs:schema attributeFormDefault="unqualified" elementFormDefault="qualified" xmlns:xs="http://www.w3.org/2001/XMLSchema">

<xs:element name="employee">

<xs:complexType>

<xs:sequence>

<xs:element name="firstName" type="xs:string" />

<xs:element name="company" type="xs:string" />

<xs:element name="mobileNumber" type="xs:string" />

</xs:sequence>

</xs:complexType>

</xs:element>

</xs:schema>

Json validation schema

{

"$schema": "http://json-schema.org/draft-04/schema#",

"type": "object",

"properties": {

"employeeName": {

"type": "string"

},

"company": {

"type": "string"

},

"mobileNumber": {

"type": "string",

"minLength": 10,

"maxLength": 10

},

"department": {

"type": "string"

}

},

"required": [

"employeeName",

"company",

"mobileNumber",

"department"

]

}

Step 6: Testing with different use cases

• HTTP request with correct payload

curl -X POST "https://api.prod.yenlo.connext.com/logger_test/1.0/employee" -H "accept: */*" -H "Content-Type: application/xml" -H "Authorization: Bearer 79933c7e-63fe-36f9-849b-25fc9aa7c46b" -d "<?xml version=\"1.0\" encoding=\"UTF-8\"?><!-- XML example cannot be generated; root element name is undefined --><employee><firstName>Randika</firstName><company>yenlo</company><mobileNumber>0718207205</mobileNumber></employee>" -v

Output log:

• HTTP request with incorrect payload(missing essential element- mobileNumber)

curl -X POST “https://api.prod.yenlo.connext.com/logger_test/1.0/employee” -H “accept: */*” -H “Content-Type: application/xml” -H “Authorization: Bearer 79933c7e-63fe-36f9-849b-25fc9aa7c46b” -d “<?xml version=\”1.0\” encoding=\”UTF-8\”?><!– XML example cannot be generated; root element name is undefined –><employee><firstName>Randika</firstName><company>yenlo</company></employee>” -v

Output log:

CNXT2][2023-03-08 07:24:26,664]  INFO correlation = 1fddb17e-6776-4ef7-ba86-516502326c2d, direction = IN, method = POST, resource = /yenlo/employee, correlationOrder = 1 {INFOLOGS}

, ERROR_DETAIL = org.xml.sax.SAXParseException; cvc-complex-type.2.4.b: The content of element ’employee’ is not complete. One of ‘{mobileNumber}’ is expected.

        at org.apache.xerces.util.ErrorHandlerWrapper.createSAXParseException(Unknown Source)

        at org.apache.xerces.util.ErrorHandlerWrapper.error(Unknown Source)

        at org.apache.xerces.impl.XMLErrorReporter.reportError(Unknown Source)

        at org.apache.xerces.impl.XMLErrorReporter.reportError(Unknown Source)

        at org.apache.xerces.impl.XMLErrorReporter.reportError(Unknown Source)

        at org.apache.xerces.impl.xs.XMLSchemaValidator$XSIErrorReporter.reportError(Unknown Source)

        at org.apache.xerces.impl.xs.XMLSchemaValidator.reportSchemaError(Unknown S {INFOLOGS}

• Payload validation after transformation(mobileNumber less than 10 characters )

curl -X POST "https://api.prod.yenlo.connext.com/logger_test/1.0/employee" -H "accept: */*" -H "Content-Type: application/xml" -H "Authorization: Bearer 79933c7e-63fe-36f9-849b-25fc9aa7c46b" -d "<?xml version=\"1.0\" encoding=\"UTF-8\"?><!-- XML example cannot be generated; root element name is undefined --><employee><firstName>Randika</firstName><company>yenlo</company><mobileNumber>071</mobileNumber></employee>" -v

Output log:

    level: “error”

    schema: {“loadingURI”:”#”,”pointer”:”/properties/mobileNumber”}

    instance: {“pointer”:”/mobileNumber”}

    domain: “validation”

    keyword: “minLength”

    value: “071”

    found: 3

    minLength: 10

, ERROR_EXCEPTION = null {INFOLOGS}

Conclusion

It is not recommended to log the payload in INFO or ERROR log level to troubleshoot an issue with the payloads. Always try to minimize the payload logging for the debugging purposes. As I mentioned earlier, it is adding the additional cost to the system and impacting to the performance degrade. Validate mediator is a good option to validate the payload in the different stages of mediation provides descriptive enough information about the validity of the payload and data. Anyway, some situations might have to log the payload to have more analysis of the issue. But that should be logged in the DEBUG log level for the special purposes.