WSO2 EI 6.1.1 - per API DEBUG level log statements which are placed after the call mediator, are cannot be found in the relevant log file

Question

I need to log DEBUG level for a specific API. I use separate log-file for sample API:http://localhost:8280/test001. I have used per API log4j properties for this requirement(reference:https://docs.wso2.com/display/ESB490/Per-API+Logs+in+WSO2+ESB). ISSUE: DEBUG level logs which are placed after the call-mediator are cannot be found in the file.

my API :test.xml

<?xml version="1.0" encoding="UTF-8"?><api context="/test001" name="test" xmlns="http://ws.apache.org/ns/synapse">
<resource methods="GET"><inSequence>
       <log category="DEBUG" level="custom">
            <property name="DEBUG category" value="DEBUG LOG BEFORE CALL MEDIATOR"/>
        </log>

        <call>
            <endpoint>
                <http method="get" uri-template="http://localhost:8280/sample001"/>
            </endpoint>
        </call>
        <log category="DEBUG" level="custom">
            <property name="DEBUG category" value="DEBUG LOG AFTER CALL MEDIATOR"/>
        </log>
        <log level="custom">
            <property name="INFO  category" value="INFO LOG AFTER CALL MEDIATOR"/>
        </log>
        <payloadFactory media-type="xml">
            <format>
                <test>SUCCESS</test>
            </format>
            <args/>
        </payloadFactory>
        <loopback description="loop backing to out-sequence"/>
    </inSequence>
    <outSequence>
        <log category="DEBUG" level="custom">
            <property name="DEBUG category" value=" DBUG OUT SEQUENCE"/>
        </log>
        <log level="custom">
            <property name="INFO category" value="INFO OUT SEUENCE"/>
        </log>
        <send/>
    </outSequence>
    <faultSequence>
        <log category="DEBUG" level="custom">
            <property name="log DEBUG" value=" DBUG FAULT SEQUENCE"/>
        </log>
        <log level="custom">
            <property name="log DEBUG" value="INFO FAULT SEUENCE"/>
        </log>
    </faultSequence></resource></api>

my log4j configurations wso2ei-6.1.1\conf\log4j.properties:

log4j.category.API_LOGGER.test =DEBUG,COMMON_API_APPENDER
log4j.appender.test.Append = true

log4j.appender.COMMON_API_APPENDER=org.apache.log4j.DailyRollingFileAppender
log4j.appender.COMMON_API_APPENDER.File=${carbon.home}/repository/logs/commonApi.log
log4j.appender.COMMON_API_APPENDER.datePattern='.'yyyy-MM-dd
log4j.appender.COMMON_API_APPENDER.layout=org.apache.log4j.PatternLayout
log4j.appender.COMMON_API_APPENDER.layout.ConversionPattern=%d{ISO8601} [%X{ip}-%X{host}] [%t] %5p %c{1} %m%n

Note: other properties are not changed in log4j.properties file

commonApi.log:

2017-11-21 19:42:06,502 [-] [localhost-startStop-1]  INFO test Initializing API: test
2017-11-21 19:43:21,703 [-] [PassThroughMessageProcessor-1] DEBUG test DEBUG category = DEBUG LOG BEFORE CALL MEDIATOR
2017-11-21 19:43:22,021 [-] [PassThroughMessageProcessor-3] DEBUG test DEBUG category =  DBUG OUT SEQUENCE
2017-11-21 19:43:22,021 [-] [PassThroughMessageProcessor-3]  INFO test INFO category = INFO OUT SEUENCE

As you can see in the API code,log line:

DEBUG category = DEBUG LOG AFTER CALL MEDIATOR

is missing in commonApi.log file.

wso2carbon.log:

TID: [-1234] [] [2017-11-21 19:43:21,703] DEBUG {API_LOGGER.test} -  DEBUG category = DEBUG LOG BEFORE CALL MEDIATOR {API_LOGGER.test}
TID: [-1234] [] [2017-11-21 19:43:21,711]  INFO {org.apache.synapse.core.axis2.TimeoutHandler} -  This engine will expire all callbacks after GLOBAL_TIMEOUT: 120 seconds, irrespective of the timeout action, after the specified or optional timeout {org.apache.synapse.core.axis2.TimeoutHandler}
TID: [-1234] [] [2017-11-21 19:43:22,004]  INFO {org.apache.synapse.mediators.builtin.LogMediator} -  To: /sample001, MessageID: urn:uuid:c7c63feb-9c3f-46f7-b3cb-9a9d0b4fb82e, Direction: request, Envelope: <?xml version='1.0' encoding='utf-8'?><soapenv:Envelope xmlns:soapenv="http://www.w3.org/2003/05/soap-envelope"><soapenv:Body/></soapenv:Envelope> {org.apache.synapse.mediators.builtin.LogMediator}
TID: [-1234] [] [2017-11-21 19:43:22,019]  INFO {org.apache.synapse.mediators.builtin.LogMediator} -  INFO  category = INFO LOG AFTER CALL MEDIATOR {org.apache.synapse.mediators.builtin.LogMediator}
TID: [-1234] [] [2017-11-21 19:43:22,021] DEBUG {API_LOGGER.test} -  DEBUG category =  DBUG OUT SEQUENCE {API_LOGGER.test}
TID: [-1234] [] [2017-11-21 19:43:22,021]  INFO {org.apache.synapse.mediators.builtin.LogMediator} -  INFO category = INFO OUT SEUENCE {org.apache.synapse.mediators.builtin.LogMediator}
TID: [-1234] [] [2017-11-21 19:43:22,021]  INFO {API_LOGGER.test} -  INFO category = INFO OUT SEUENCE {API_LOGGER.test}

But you can see the info log line:

INFO  category = INFO LOG AFTER CALL MEDIATOR

in wso2carbon.log file(this assures the execution after call-mediator).

Note: However i can assure below things:

That the mediation flow which is written after the call-mediator is executing .(i can see info logs in console.).
Call mediator successfully responding with values.
Without the call-mediator in API,all DEBUG log lines are there in the commonApi.log file.(working as expected)
out-sequence DEBUG logs are there in the file any way.(working as expected)

Thanks in advance.!

If there error during call mediator then message will be passed to fault sequence. — simar
As I mentioned in the question, Call mediator successfully responding with values.! your comment is irrelevant to this question. — imasmohamed

prageeth prageeth · Accepted Answer · 2017-11-22T06:18:58

Are you sure that you need to use the call mediator in non-blocking mode(by default call mediator is non-blocking)? Your code works if you changed the mode to blocking as below.

<call blocking="true">

Or you can use <callout> mediator which is blocking by default to get the same result.

Since INFO logs are working, I think this could be a Bug in WSO2 IE6.

WSO2 EI 6.1.1 - per API DEBUG level log statements which are placed after the call mediator, are cannot be found in the relevant log file

1 Answers