search

SumoLogic / sumologic-log4j2-appender

Log4J 2 Appender for Sumo Logic.
Apache License 2.0
10 stars 10 forks source link

Inconsistent logging of Mule logger messages via log4j2 appender #11

Closed peterc100 closed 6 years ago

peterc100 commented 6 years ago

after raising this issue with official Sumologic support i was told that because the log4j2 appender was OSS that they did not (officially) support it and to try raising the issue here.

i'll provide an overview first, but can provide more details as necessary (i'm also not sure how much these repos are supported by Sumologic or whoever else).

in short, we are using the log4j2 appender to connect to a Sumo HTTP collector via URL, as follows, in a Mulesoft project 

  <?xml version="1.0" encoding="utf-8"?> 
  <Configuration status="info" name="sumologic" packages="com.sumologic.log4j"> 
    <Appenders> 
      <RollingFile name="file" fileName="${sys:mule.home}${sys:file.separator}logs${sys:file.separator}test-logging.log" 
        filePattern="${sys:mule.home}${sys:file.separator}logs${sys:file.separator}test-logging-%i.log"> 
        <PatternLayout pattern="%d [%t] %-5p %c - %m%n" /> 
        <SizeBasedTriggeringPolicy size="10 MB" /> 
        <DefaultRolloverStrategy max="10"/> 
      </RollingFile> 
      <!-- sumologic appender / collector url --> 
      <SumoLogicAppender name="SumoAppender" url="${sys:sumologic.appender.url}"> 
        <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss,SSS Z} [%t] %-5p %c - %m%n" /> 
        </SumoLogicAppender> 
      </Appenders> 
      ...
      <Loggers> 
        ... 
        <AsyncRoot level="INFO"> 
          <AppenderRef ref="file" /> 
          <AppenderRef ref="SumoAppender" /> 
        </AsyncRoot> 
      </Loggers> 
  </Configuration>

and i find that while i'm seeing Mule logging messages appear under the category on Sumologic, eg:

  26  10/07/2018
  14:48:18.295 +1000  
  2018-07-10 14:48:18,295 +1000 [main] INFO  org.mule.processor.SedaStageLifecycleManager - Initialising service: test-sumologic-by-logger-test.stage1
  Host: 103.199.119.138  Name: Http Input  Category: tmp/monkey/business-two 
  27  10/07/2018
  14:48:18.288 +1000  
  2018-07-10 14:48:18,288 +1000 [main] INFO  org.mule.exception.DefaultMessagingExceptionStrategy - Initialising exception listener: org.mule.exception.DefaultMessagingExceptionStrategy@2f95653f
  Host: 103.199.119.138  Name: Http Input  Category: tmp/monkey/business-two 
  28  10/07/2018
  14:48:18.288 +1000  
  2018-07-10 14:48:18,288 +1000 [main] INFO  org.mule.construct.FlowConstructLifecycleManager - Initialising flow: test-sumologic-by-logger-test
  Host: 103.199.119.138  Name: Http Input  Category: tmp/monkey/business-two 
  29  10/07/2018
  14:48:18.247 +1000  
  2018-07-10 14:48:18,247 +1000 [main] INFO  org.mule.processor.SedaStageLifecycleManager - Initialising service: test-sumologic.stage1
  Host: 103.199.119.138  Name: Http Input  Category: tmp/monkey/business-two 
  30  10/07/2018
  14:48:18.198 +1000  
  2018-07-10 14:48:18,198 +1000 [main] INFO  org.mule.exception.DefaultMessagingExceptionStrategy - Initialising exception listener: org.mule.exception.DefaultMessagingExceptionStrategy@d653e41
  Host: 103.199.119.138  Name: Http Input  Category: tmp/monkey/business-two 
  31  10/07/2018
  14:48:18.197 +1000  
  2018-07-10 14:48:18,197 +1000 [main] INFO  org.mule.construct.FlowConstructLifecycleManager - Initialising flow: test-sumologic
  Host: 103.199.119.138  Name: Http Input  Category: tmp/monkey/business-two 
  32  10/07/2018
  14:48:18.181 +1000  
  2018-07-10 14:48:18,181 +1000 [main] INFO  org.mule.lifecycle.AbstractLifecycleManager - Initialising model: _muleSystemModel
  Host: 103.199.119.138  Name: Http Input  Category: tmp/monkey/business-two 
  33  10/07/2018
  14:48:17.893 +1000  
  2018-07-10 14:48:17,893 +1000 [main] INFO  org.mule.util.journal.TransactionJournal - Using files for tx logs /home/vagrant/AnypointStudio/workspace-6-3/test-logging/./.mule/queue-xa-tx-log/tx1.log and /home/vagrant/AnypointStudio/workspace-6-3/test-logging/./.mule/queue-xa-tx-log/tx2.log
  Host: 103.199.119.138  Name: Http Input  Category: tmp/monkey/business-two 
  34  10/07/2018
  14:48:17.584 +1000  
  2018-07-10 14:48:17,584 +1000 [main] INFO  org.mule.util.journal.TransactionJournal - Using files for tx logs /home/vagrant/AnypointStudio/workspace-6-3/test-logging/./.mule/queue-tx-log/tx1.log and /home/vagrant/AnypointStudio/workspace-6-3/test-logging/./.mule/queue-tx-log/tx2.log
  Host: 103.199.119.138  Name: Http Input  Category: tmp/monkey/business-two 
  35  10/07/2018
  14:48:17.090 +1000  
  2018-07-10 14:48:17,090 +1000 [main] WARN  org.mule.module.ognl.expression.OgnlExpressionEvaluator - OGNL module is deprecated and will be removed in Mule 4.0. Use MEL expressions instead.
  Host: 103.199.119.138  Name: Http Input  Category: tmp/monkey/business-two

that the messages i'm logging in the actual Mule flow, via the Mule standard logging component, are not appearing, even though they use the same logging mechanism (log4j2) as Mule itself

  psc>>>> log-sumologic-by-logger-sub-start
  psc>>>> hello, world from mule...
  psc>>>> log-sumologic-by-logger-sub-end

sometimes we see the first message, but not the next two and, most recently, all the messages fail to appear; note that all the messages are visible in the Mule / Anypoint Studio console.

this has been happening repeatedly in past days (tues-wed, 10-11Jul18 AEST) and in recent weeks, while, a month or two back, it all seemed to work consistently.

~p

peterc100 commented 6 years ago

here's what i see in the Mule console:

Running test-sumologic-by-logger-test
INFO  2018-07-11 10:34:49,311 [main] /tmp/monkey/business-two: psc>>>> log-sumologic-by-logger-sub-start
INFO  2018-07-11 10:34:49,329 [main] /tmp/monkey/business-two: psc>>>>  hello, world from mule!, using logger! log4j2.mule.test.var = 'hello-from-log4j2.mule.test.var-set-in-mule-app.properties'
INFO  2018-07-11 10:34:49,333 [main] /tmp/monkey/business-two: psc>>>> log-sumologic-by-logger-sub-end

but absolutely no sign of these in Sumologic (while we do see the Mule messages in the initial post) using _sourceCategory=tmp/monkey/business-two "psc"

rvmiller89 commented 6 years ago

@peterc100 can you confirm if this is a short-lived application, e.g., is it being stopped soon after emitting those log lines? There is an issue that was recently resolved where unflushed log lines were lost if the application shut down.

peterc100 commented 6 years ago

hey, @rvmiller89, thanks for the response.

yes, this is most definitely a short-lived app, it was a simple test mule flow that just pumped out a few messages before ending so that i could see if those messages arrived at the sumologic host. our longer-lived apps still seem able to send messages to sumologic too, it's just that those send so many we couldn't confirm that they'd all arrived -- hence the use of the test app to see if there was some sort of basic problem.

i notice we're using v1.2 of the appender and it's now up to v1.4 so i should upgrade our pom.xml and re-test.

thanks for the feedback.

rvmiller89 commented 6 years ago

No problem @peterc100 , also note that in this new flushAllBeforeStopping flag is disabled by default, so to enable you'll also have to set the log4j configuration property:

flushAllBeforeStopping="true"

Example in https://github.com/SumoLogic/sumologic-log4j2-appender#example-with-optional-parameters

peterc100 commented 6 years ago

ok, @rvmiller89, so using 

<dependency>
    <groupId>com.sumologic.plugins.log4j</groupId>
    <artifactId>sumologic-log4j2-appender</artifactId>
    <version>1.4</version>
</dependency>

with a log4j2.xml containing

<Configuration status="info" name="sumologic" packages="com.sumologic.log4j">
    <Appenders>
        ....
        <!-- sumologic appender / collector url -->
        <SumoLogicAppender name="SumoAppender" url="${sys:sumologic.appender.url}" flushAllBeforeStopping="true">
            <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss,SSS Z} [%t] %-5p %c - %m%n" />
        </SumoLogicAppender>
    ...

the first attempt (with no forced delay at the end of the flow) i saw the first ~20 messages from mule appear on Sumologic with about ~200 missing

INFO  2018-07-13 11:04:00,229 [Thread-2] org.mule.munit.plugins.coverage.server.MunitCoverageServer: Waiting for coverage connection 
INFO  2018-07-13 11:04:00,265 [main] org.mule.munit.runner.MuleContextManager: Loading mule-app.properties ...
INFO  2018-07-13 11:04:00,531 [main] org.mule.munit.runner.domain.MunitDomainContextBuilder: Loading mule-deploy.properties ...
2018-07-13 11:04:00,614 main INFO Log4j appears to be running in a Servlet environment, but there's no log4j-web module available. If you want better web container support, please add the log4j-web JAR to your web archive or server lib directory.
INFO  2018-07-13 11:04:01,259 [main] org.mule.lifecycle.AbstractLifecycleManager: Initialising RegistryBroker
INFO  2018-07-13 11:04:01,680 [main] org.mule.module.extension.internal.manager.DefaultExtensionManager: Starting discovery of extensions
INFO  2018-07-13 11:04:02,240 [main] org.mule.module.extension.internal.manager.DefaultExtensionManager: Discovered 1 extensions
INFO  2018-07-13 11:04:02,240 [main] org.mule.module.extension.internal.manager.DefaultExtensionManager: Registering extension validation (version 3.9)
INFO  2018-07-13 11:04:02,377 [main] org.mule.munit.runner.spring.config.MunitApplicationContext: Refreshing org.mule.munit.runner.spring.config.MunitApplicationContext@181d7f28: startup date [Fri Jul 13 11:04:02 AEST 2018]; root of context hierarchy
INFO  2018-07-13 11:04:06,087 [main] org.mule.config.spring.processors.NoDevkitInjectorProcessor: JSR-330 'javax.inject.Inject' annotation found and supported for autowiring
WARN  2018-07-13 11:04:09,773 [main] org.mule.module.ognl.expression.OgnlExpressionEvaluator: OGNL module is deprecated and will be removed in Mule 4.0. Use MEL expressions instead.
INFO  2018-07-13 11:04:10,296 [main] org.mule.util.journal.TransactionJournal: Using files for tx logs /home/vagrant/AnypointStudio/workspace-6-4/test-logging/./.mule/queue-tx-log/tx1.log and /home/vagrant/AnypointStudio/workspace-6-4/test-logging/./.mule/queue-tx-log/tx2.log
INFO  2018-07-13 11:04:10,316 [main] org.mule.util.journal.TransactionJournal: Using files for tx logs /home/vagrant/AnypointStudio/workspace-6-4/test-logging/./.mule/queue-xa-tx-log/tx1.log and /home/vagrant/AnypointStudio/workspace-6-4/test-logging/./.mule/queue-xa-tx-log/tx2.log
INFO  2018-07-13 11:04:10,446 [main] org.mule.lifecycle.AbstractLifecycleManager: Initialising model: _muleSystemModel
INFO  2018-07-13 11:04:10,471 [main] org.mule.construct.FlowConstructLifecycleManager: Initialising flow: test-sumologic
INFO  2018-07-13 11:04:10,478 [main] org.mule.exception.DefaultMessagingExceptionStrategy: Initialising exception listener: org.mule.exception.DefaultMessagingExceptionStrategy@445bce9a
INFO  2018-07-13 11:04:10,517 [main] org.mule.processor.SedaStageLifecycleManager: Initialising service: test-sumologic.stage1
INFO  2018-07-13 11:04:10,548 [main] org.mule.construct.FlowConstructLifecycleManager: Initialising flow: test-sumologic-by-logger-test
INFO  2018-07-13 11:04:10,556 [main] org.mule.exception.DefaultMessagingExceptionStrategy: Initialising exception listener: org.mule.exception.DefaultMessagingExceptionStrategy@168142da
INFO  2018-07-13 11:04:10,566 [main] org.mule.processor.SedaStageLifecycleManager: Initialising service: test-sumologic-by-logger-test.stage1
INFO  2018-07-13 11:04:10,572 [main] org.mule.construct.FlowConstructLifecycleManager: Initialising flow: test-sumologic-by-groovy-test
INFO  2018-07-13 11:04:10,572 [main] org.mule.exception.DefaultMessagingExceptionStrategy: Initialising exception listener: org.mule.exception.DefaultMessagingExceptionStrategy@39ab5ef7
INFO  2018-07-13 11:04:10,583 [main] org.mule.processor.SedaStageLifecycleManager: Initialising service: test-sumologic-by-groovy-test.stage1
INFO  2018-07-13 11:04:10,585 [main] org.mule.component.ComponentLifecycleManager: Initialising component: component.1082640380

i then stuck a groovy sleep step in to delay the end of the flow

sleep(60000);
return message.payload;

and all the messages then made their way to Sumologic including the missing flow messages

13/07/2018
11:32:48.403 +1000  
2018-07-13 11:32:48,403 +1000 [main] INFO  /tmp/monkey/business-two - psc>>>> log-sumologic-by-logger-sub-end
Host: 103.199.119.138  Name: Http Input  Category: tmp/monkey/business-two 
2 13/07/2018
11:32:47.748 +1000  
2018-07-13 11:32:47,748 +1000 [main] INFO  /tmp/monkey/business-two - psc>>>> hello, world from mule!, using logger! log4j2.mule.test.var = 'hello-from-log4j2.mule.test.var-set-in-mule-app.properties'
Host: 103.199.119.138  Name: Http Input  Category: tmp/monkey/business-two 
3 13/07/2018
11:32:46.703 +1000  
2018-07-13 11:32:46,703 +1000 [main] INFO  /tmp/monkey/business-two - psc>>>> log-sumologic-by-logger-sub-start
Host: 103.199.119.138  Name: Http Input  Category: tmp/monkey/business-two

so there might still be a problem with flows ending too soon.

this should be less of an issue with proper mule apps which stay up permanently on Cloudhub (with a daily poll kicking the flows off), tho.

peterc100 commented 6 years ago

i also wonder whether our use of <AsyncRoot> rather than just <Root> might be a problem?

<AsyncRoot level="INFO">
    <AppenderRef ref="file" />
    <AppenderRef ref="SumoAppender" />
</AsyncRoot>
peterc100 commented 6 years ago

fyi, no real improvement going to <Root> from <AsyncRoot>.

rvmiller89 commented 6 years ago

@peterc100 can you enable debug lines for Sumo Appender and paste the output of your test here? 

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="debug">
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss,SSS Z} [%t] %-5p %c - %m%n" />
        </Console>
        <SumoLogicAppender
                name="SumoAppender"
                flushAllBeforeStopping="true"
                url="[collector-url]"
                >
            <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss,SSS Z} [%t] %-5p %c - %m%n" />
        </SumoLogicAppender>
    </Appenders>
    <Loggers>
        <Root level="all" additivity="false">
            <AppenderRef ref="Console" />
            <AppenderRef ref="SumoAppender" />
        </Root>
    </Loggers>
</Configuration>

We're looking for lines like:

2018-07-13 10:41:40,537 main DEBUG Shutdown hook enabled. Registering a new one.
...
2018-07-13 10:41:40,545 pool-1-thread-1 DEBUG Stopping SumoLogicAppender SumoAppender
2018-07-13 10:43:17,284 pool-1-thread-1 DEBUG Sending out data
2018-07-13 10:43:17,636 pool-1-thread-1 DEBUG Successfully sent log request to Sumo Logic
2018-07-13 10:43:17,636 pool-1-thread-1 DEBUG flusher has been stopped
2018-07-13 10:43:17,638 pool-1-thread-1 DEBUG SumoLogicAppender SumoAppender has been stopped
peterc100 commented 6 years ago

i've pasted the debug output below.

unfortunately, no two days seem alike in the world of Mule -- if you look at the last couple of lines you'll see

2018-07-16 15:41:32,574 main DEBUG Mon Jul 16 15:41:32 AEST 2018 - Flushing and sending out 3 messages (0 messages left)
2018-07-16 15:41:32,575 main DEBUG Sending out data

and the mule flow stops at this point and never ends and no messages appear at the sumologic host either.

this wasn't happening last week, instead the flow ended and we got some messages, but not all, at sumologic's end until i left the 60sec delay in. this makes me think that Mule or the Anypoint Studio IDE may have cached the old appender (v1.2) and now that it's a new day and everything has been re-booted we're seeing different behaviour.

here's the full output:

[org.mule.munit.remote.RemoteRunner]Run Started
Coverage port: 53329 resources: config.xml,test-sumologic.xml 
2018-07-16 15:41:24,463 main DEBUG Initializing configuration XmlConfiguration[location=/home/vagrant/AnypointStudio/workspace-6-4/test-logging/target/test-classes/log4j2-test.xml]
2018-07-16 15:41:24,637 main DEBUG Installed script engines
2018-07-16 15:41:25,089 main DEBUG Oracle Nashorn Version: 1.8.0_151, Language: ECMAScript, Threading: Not Thread Safe, Compile: true, Names: {nashorn, Nashorn, js, JS, JavaScript, javascript, ECMAScript, ecmascript}
2018-07-16 15:41:25,292 main DEBUG Mozilla Rhino Version: 1.6 release 2, Language: EmbeddedECMAScript, Threading: MULTITHREADED, Compile: true, Names: {ejs, EmbeddedJavaScript, embeddedjavascript}
2018-07-16 15:41:25,320 main DEBUG Groovy Scripting Engine Version: 2.0, Language: Groovy, Threading: MULTITHREADED, Compile: true, Names: {groovy, Groovy}
2018-07-16 15:41:25,323 main DEBUG Mozilla Rhino Version: 1.6R5, Language: ECMAScript, Threading: MULTITHREADED, Compile: true, Names: {rhino-nonjdk, js, rhino, JavaScript, javascript, ECMAScript, ecmascript}
2018-07-16 15:41:25,581 main DEBUG JSR 223 JRuby Engine Version: 1.7.27, Language: ruby, Threading: THREAD-ISOLATED, Compile: true, Names: {ruby, jruby}
2018-07-16 15:41:26,703 main DEBUG Scala Interpreter Version: 1.0, Language: Scala, Threading: Not Thread Safe, Compile: true, Names: {scala}
2018-07-16 15:41:29,991 main DEBUG jython Version: 2.7.3, Language: python, Threading: MULTITHREADED, Compile: true, Names: {python, jython}
2018-07-16 15:41:30,015 main DEBUG Took 0.022947 seconds to load 1 plugins from package com.sumologic.log4j
2018-07-16 15:41:30,016 main DEBUG PluginManager 'Core' found 113 plugins
2018-07-16 15:41:30,017 main DEBUG PluginManager 'Level' found 0 plugins
2018-07-16 15:41:30,023 main DEBUG PluginManager 'Lookup' found 13 plugins
2018-07-16 15:41:30,028 main DEBUG Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout].
2018-07-16 15:41:30,067 main DEBUG PluginManager 'TypeConverter' found 26 plugins
2018-07-16 15:41:30,086 main DEBUG PatternLayout$Builder(pattern="%-5p %d [%t] %c: %m%n", PatternSelector=null, Configuration(sumologic), Replace=null, charset="null", alwaysWriteExceptions="null", disableAnsi="null", noConsoleNoAnsi="null", header="null", footer="null")
2018-07-16 15:41:30,086 main DEBUG PluginManager 'Converter' found 41 plugins
2018-07-16 15:41:30,109 main DEBUG Building Plugin[name=appender, class=org.apache.logging.log4j.core.appender.ConsoleAppender].
2018-07-16 15:41:30,160 main DEBUG ConsoleAppender$Builder(target="SYSTEM_OUT", follow="null", direct="null", bufferedIo="null", bufferSize="null", immediateFlush="null", ignoreExceptions="null", PatternLayout(%-5p %d [%t] %c: %m%n), name="Console", Configuration(sumologic), Filter=null)
2018-07-16 15:41:30,162 main DEBUG Starting OutputStreamManager SYSTEM_OUT.false.false
2018-07-16 15:41:30,162 main DEBUG Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout].
2018-07-16 15:41:30,164 main DEBUG PatternLayout$Builder(pattern="%d{yyyy-MM-dd HH:mm:ss,SSS Z} [%t] %-5p %c - %m%n", PatternSelector=null, Configuration(sumologic), Replace=null, charset="null", alwaysWriteExceptions="null", disableAnsi="null", noConsoleNoAnsi="null", header="null", footer="null")
2018-07-16 15:41:30,243 main DEBUG Building Plugin[name=appender, class=com.sumologic.log4j.SumoLogicAppender].
2018-07-16 15:41:30,278 main DEBUG createAppender(name="SumoAppender", PatternLayout(%d{yyyy-MM-dd HH:mm:ss,SSS Z} [%t] %-5p %c - %m%n), Filter=null, url="${sys:sumologic.appender.url}", proxyAuth="null", proxyHost="null", proxyPort="0", proxyUser="null", proxyPassword="null", proxyDomain="null", retryInterval="10000", connectionTimeout="1000", socketTimeout="60000", messagesPerRequest="100", maxFlushInterval="10000", sourceName="null", sourceCategory="null", sourceHost="null", flushingAccuracy="250", maxQueueSizeBytes="1000000", flushAllBeforeStopping="true")
2018-07-16 15:41:30,768 main DEBUG Building Plugin[name=appenders, class=org.apache.logging.log4j.core.config.AppendersPlugin].
2018-07-16 15:41:30,768 main DEBUG createAppenders(={Console, SumoAppender})
2018-07-16 15:41:30,768 main DEBUG Building Plugin[name=asyncLogger, class=org.apache.logging.log4j.core.async.AsyncLoggerConfig].
2018-07-16 15:41:30,771 main DEBUG createLogger(additivity="null", level="WARN", name="org.apache.cxf", includeLocation="null", ={}, ={}, Configuration(sumologic), Filter=null)
2018-07-16 15:41:30,777 main DEBUG Building Plugin[name=asyncLogger, class=org.apache.logging.log4j.core.async.AsyncLoggerConfig].
2018-07-16 15:41:30,779 main DEBUG createLogger(additivity="null", level="WARN", name="org.apache", includeLocation="null", ={}, ={}, Configuration(sumologic), Filter=null)
2018-07-16 15:41:30,779 main DEBUG Building Plugin[name=asyncLogger, class=org.apache.logging.log4j.core.async.AsyncLoggerConfig].
2018-07-16 15:41:30,784 main DEBUG createLogger(additivity="null", level="WARN", name="org.springframework.beans.factory", includeLocation="null", ={}, ={}, Configuration(sumologic), Filter=null)
2018-07-16 15:41:30,785 main DEBUG Building Plugin[name=asyncLogger, class=org.apache.logging.log4j.core.async.AsyncLoggerConfig].
2018-07-16 15:41:30,785 main DEBUG createLogger(additivity="null", level="INFO", name="org.mule", includeLocation="null", ={}, ={}, Configuration(sumologic), Filter=null)
2018-07-16 15:41:30,786 main DEBUG Building Plugin[name=asyncLogger, class=org.apache.logging.log4j.core.async.AsyncLoggerConfig].
2018-07-16 15:41:30,786 main DEBUG createLogger(additivity="null", level="INFO", name="com.mulesoft", includeLocation="null", ={}, ={}, Configuration(sumologic), Filter=null)
2018-07-16 15:41:30,789 main DEBUG Building Plugin[name=asyncLogger, class=org.apache.logging.log4j.core.async.AsyncLoggerConfig].
2018-07-16 15:41:30,794 main DEBUG createLogger(additivity="null", level="WARN", name="org.jetel", includeLocation="null", ={}, ={}, Configuration(sumologic), Filter=null)
2018-07-16 15:41:30,795 main DEBUG Building Plugin[name=asyncLogger, class=org.apache.logging.log4j.core.async.AsyncLoggerConfig].
2018-07-16 15:41:30,795 main DEBUG createLogger(additivity="null", level="WARN", name="Tracking", includeLocation="null", ={}, ={}, Configuration(sumologic), Filter=null)
2018-07-16 15:41:30,796 main DEBUG Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef].
2018-07-16 15:41:30,796 main DEBUG createAppenderRef(ref="Console", level="null", Filter=null)
2018-07-16 15:41:30,797 main DEBUG Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef].
2018-07-16 15:41:30,798 main DEBUG createAppenderRef(ref="SumoAppender", level="null", Filter=null)
2018-07-16 15:41:30,798 main DEBUG Building Plugin[name=asyncRoot, class=org.apache.logging.log4j.core.async.AsyncLoggerConfig$RootLogger].
2018-07-16 15:41:30,801 main DEBUG createLogger(additivity="null", level="INFO", includeLocation="null", ={Console, SumoAppender}, ={}, Configuration(sumologic), Filter=null)
2018-07-16 15:41:30,801 main DEBUG Building Plugin[name=loggers, class=org.apache.logging.log4j.core.config.LoggersPlugin].
2018-07-16 15:41:30,802 main DEBUG createLoggers(={org.apache.cxf, org.apache, org.springframework.beans.factory, org.mule, com.mulesoft, org.jetel, Tracking, root})
2018-07-16 15:41:30,803 main DEBUG Configuration XmlConfiguration[location=/home/vagrant/AnypointStudio/workspace-6-4/test-logging/target/test-classes/log4j2-test.xml] initialized
2018-07-16 15:41:30,803 main DEBUG Starting configuration XmlConfiguration[location=/home/vagrant/AnypointStudio/workspace-6-4/test-logging/target/test-classes/log4j2-test.xml]
2018-07-16 15:41:30,833 main DEBUG Starting AsyncLoggerConfig disruptor for this configuration with ringbufferSize=262144, waitStrategy=TimeoutBlockingWaitStrategy, exceptionHandler=org.apache.logging.log4j.core.async.AsyncLoggerConfigDefaultExceptionHandler@645dc557...
2018-07-16 15:41:30,842 main DEBUG Started configuration XmlConfiguration[location=/home/vagrant/AnypointStudio/workspace-6-4/test-logging/target/test-classes/log4j2-test.xml] OK.
2018-07-16 15:41:30,847 main DEBUG Shutting down OutputStreamManager SYSTEM_OUT.false.false-1
2018-07-16 15:41:30,848 main DEBUG Shut down OutputStreamManager SYSTEM_OUT.false.false-1, all resources released: true
2018-07-16 15:41:30,848 main DEBUG Appender DefaultConsole-1 stopped with status true
2018-07-16 15:41:30,854 main DEBUG Stopped org.apache.logging.log4j.core.config.DefaultConfiguration@6eceb130 OK
2018-07-16 15:41:31,090 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1
2018-07-16 15:41:31,093 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=StatusLogger
2018-07-16 15:41:31,098 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=ContextSelector
2018-07-16 15:41:31,103 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=
2018-07-16 15:41:31,104 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=,subtype=RingBuffer
2018-07-16 15:41:31,107 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=Tracking
2018-07-16 15:41:31,108 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=Tracking,subtype=RingBuffer
2018-07-16 15:41:31,108 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.apache.cxf
2018-07-16 15:41:31,108 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.apache.cxf,subtype=RingBuffer
2018-07-16 15:41:31,109 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.springframework.beans.factory
2018-07-16 15:41:31,109 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.springframework.beans.factory,subtype=RingBuffer
2018-07-16 15:41:31,110 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.mule
2018-07-16 15:41:31,110 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.mule,subtype=RingBuffer
2018-07-16 15:41:31,111 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.jetel
2018-07-16 15:41:31,112 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.jetel,subtype=RingBuffer
2018-07-16 15:41:31,112 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.apache
2018-07-16 15:41:31,113 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.apache,subtype=RingBuffer
2018-07-16 15:41:31,113 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=com.mulesoft
2018-07-16 15:41:31,114 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=com.mulesoft,subtype=RingBuffer
2018-07-16 15:41:31,115 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Appenders,name=Console
2018-07-16 15:41:31,115 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Appenders,name=SumoAppender
2018-07-16 15:41:31,119 main DEBUG Reconfiguration complete for context[name=5700d6b1] at URI /home/vagrant/AnypointStudio/workspace-6-4/test-logging/target/test-classes/log4j2-test.xml (org.apache.logging.log4j.core.LoggerContext@4b476233) with optional ClassLoader: null
2018-07-16 15:41:31,120 main DEBUG Shutdown hook enabled. Registering a new one.
2018-07-16 15:41:31,121 main DEBUG LoggerContext[name=5700d6b1, org.apache.logging.log4j.core.LoggerContext@4b476233] started OK.
[org.mule.munit.remote.notification.SocketMessageHandler]Connected to localhost in port 43582
INFO  2018-07-16 15:41:31,145 [Thread-2] org.mule.munit.plugins.coverage.server.MunitCoverageServer: Waiting for coverage connection 
2018-07-16 15:41:31,147 Log4j2-TF-1-AsyncLoggerConfig-1 DEBUG Sending messge to Sumo: 2018-07-16 15:41:31,145 +1000 [Thread-2] INFO  org.mule.munit.plugins.coverage.server.MunitCoverageServer - Waiting for coverage connection 

2018-07-16 15:41:31,156 Thread-2 DEBUG AsyncLogger.ThreadNameStrategy=CACHED
INFO  2018-07-16 15:41:31,233 [main] org.mule.munit.runner.MuleContextManager: Loading mule-app.properties ...
2018-07-16 15:41:31,233 Log4j2-TF-1-AsyncLoggerConfig-1 DEBUG Sending messge to Sumo: 2018-07-16 15:41:31,233 +1000 [main] INFO  org.mule.munit.runner.MuleContextManager - Loading mule-app.properties ...

INFO  2018-07-16 15:41:31,400 [main] org.mule.munit.runner.domain.MunitDomainContextBuilder: Loading mule-deploy.properties ...
2018-07-16 15:41:31,400 Log4j2-TF-1-AsyncLoggerConfig-1 DEBUG Sending messge to Sumo: 2018-07-16 15:41:31,400 +1000 [main] INFO  org.mule.munit.runner.domain.MunitDomainContextBuilder - Loading mule-deploy.properties ...

2018-07-16 15:41:31,446 main DEBUG Reconfiguration started for context[name=5700d6b1] at URI null (org.apache.logging.log4j.core.LoggerContext@4b476233) with optional ClassLoader: null
2018-07-16 15:41:31,448 main DEBUG Using configurationFactory org.apache.logging.log4j.core.config.ConfigurationFactory$Factory@2e1add6f
2018-07-16 15:41:31,465 main INFO Log4j appears to be running in a Servlet environment, but there's no log4j-web module available. If you want better web container support, please add the log4j-web JAR to your web archive or server lib directory.
2018-07-16 15:41:31,487 main DEBUG Initializing configuration XmlConfiguration[location=/home/vagrant/AnypointStudio/workspace-6-4/test-logging/target/test-classes/log4j2-test.xml]
2018-07-16 15:41:31,493 main DEBUG Installed script engines
2018-07-16 15:41:31,538 main DEBUG Mozilla Rhino Version: 1.6 release 2, Language: EmbeddedECMAScript, Threading: MULTITHREADED, Compile: true, Names: {ejs, EmbeddedJavaScript, embeddedjavascript}
2018-07-16 15:41:31,542 main DEBUG Groovy Scripting Engine Version: 2.0, Language: Groovy, Threading: MULTITHREADED, Compile: true, Names: {groovy, Groovy}
2018-07-16 15:41:31,555 main DEBUG JSR 223 JRuby Engine Version: 1.7.27, Language: ruby, Threading: THREAD-ISOLATED, Compile: true, Names: {ruby, jruby}
2018-07-16 15:41:31,583 main DEBUG Mozilla Rhino Version: 1.6R5, Language: ECMAScript, Threading: MULTITHREADED, Compile: true, Names: {rhino-nonjdk, js, rhino, JavaScript, javascript, ECMAScript, ecmascript}
2018-07-16 15:41:31,607 main DEBUG Scala Interpreter Version: 1.0, Language: Scala, Threading: Not Thread Safe, Compile: true, Names: {scala}
2018-07-16 15:41:32,366 main DEBUG jython Version: 2.7.3, Language: python, Threading: MULTITHREADED, Compile: true, Names: {python, jython}
2018-07-16 15:41:32,382 main DEBUG Oracle Nashorn Version: 1.8.0_151, Language: ECMAScript, Threading: Not Thread Safe, Compile: true, Names: {nashorn, Nashorn, js, JS, JavaScript, javascript, ECMAScript, ecmascript}
2018-07-16 15:41:32,385 main DEBUG PluginManager 'Core' found 113 plugins
2018-07-16 15:41:32,386 main DEBUG PluginManager 'Level' found 0 plugins
2018-07-16 15:41:32,388 main DEBUG PluginManager 'Lookup' found 13 plugins
2018-07-16 15:41:32,389 main DEBUG Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout].
2018-07-16 15:41:32,393 main DEBUG PatternLayout$Builder(pattern="%-5p %d [%t] %c: %m%n", PatternSelector=null, Configuration(sumologic), Replace=null, charset="null", alwaysWriteExceptions="null", disableAnsi="null", noConsoleNoAnsi="null", header="null", footer="null")
2018-07-16 15:41:32,394 main DEBUG PluginManager 'Converter' found 41 plugins
2018-07-16 15:41:32,396 main DEBUG Building Plugin[name=appender, class=org.apache.logging.log4j.core.appender.ConsoleAppender].
2018-07-16 15:41:32,398 main DEBUG ConsoleAppender$Builder(target="SYSTEM_OUT", follow="null", direct="null", bufferedIo="null", bufferSize="null", immediateFlush="null", ignoreExceptions="null", PatternLayout(%-5p %d [%t] %c: %m%n), name="Console", Configuration(sumologic), Filter=null)
2018-07-16 15:41:32,399 main DEBUG Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout].
2018-07-16 15:41:32,401 main DEBUG PatternLayout$Builder(pattern="%d{yyyy-MM-dd HH:mm:ss,SSS Z} [%t] %-5p %c - %m%n", PatternSelector=null, Configuration(sumologic), Replace=null, charset="null", alwaysWriteExceptions="null", disableAnsi="null", noConsoleNoAnsi="null", header="null", footer="null")
2018-07-16 15:41:32,409 main DEBUG Building Plugin[name=appender, class=com.sumologic.log4j.SumoLogicAppender].
2018-07-16 15:41:32,411 main DEBUG createAppender(name="SumoAppender", PatternLayout(%d{yyyy-MM-dd HH:mm:ss,SSS Z} [%t] %-5p %c - %m%n), Filter=null, url="https://collectors.au.sumologic.com/receiver/v1/http/ZaVnC4dhaV3VUtT1kQx8VtT0XTyBSnmeVHv8ZsTDNCZN9Ol6zc9Dao5UvKzhbmMniVTXXKEcWN7cQJLLepbk3adJxz84dm7c8Fl9s8T-2ldvNeFY28MgGA==", proxyAuth="null", proxyHost="null", proxyPort="0", proxyUser="null", proxyPassword="null", proxyDomain="null", retryInterval="10000", connectionTimeout="1000", socketTimeout="60000", messagesPerRequest="100", maxFlushInterval="10000", sourceName="null", sourceCategory="null", sourceHost="null", flushingAccuracy="250", maxQueueSizeBytes="1000000", flushAllBeforeStopping="true")
2018-07-16 15:41:32,418 main DEBUG Building Plugin[name=appenders, class=org.apache.logging.log4j.core.config.AppendersPlugin].
2018-07-16 15:41:32,432 main DEBUG createAppenders(={Console, SumoAppender})
2018-07-16 15:41:32,434 main DEBUG Building Plugin[name=asyncLogger, class=org.apache.logging.log4j.core.async.AsyncLoggerConfig].
2018-07-16 15:41:32,436 main DEBUG createLogger(additivity="null", level="WARN", name="org.apache.cxf", includeLocation="null", ={}, ={}, Configuration(sumologic), Filter=null)
2018-07-16 15:41:32,438 main DEBUG Building Plugin[name=asyncLogger, class=org.apache.logging.log4j.core.async.AsyncLoggerConfig].
2018-07-16 15:41:32,444 main DEBUG createLogger(additivity="null", level="WARN", name="org.apache", includeLocation="null", ={}, ={}, Configuration(sumologic), Filter=null)
2018-07-16 15:41:32,445 main DEBUG Building Plugin[name=asyncLogger, class=org.apache.logging.log4j.core.async.AsyncLoggerConfig].
2018-07-16 15:41:32,454 main DEBUG createLogger(additivity="null", level="WARN", name="org.springframework.beans.factory", includeLocation="null", ={}, ={}, Configuration(sumologic), Filter=null)
2018-07-16 15:41:32,455 main DEBUG Building Plugin[name=asyncLogger, class=org.apache.logging.log4j.core.async.AsyncLoggerConfig].
2018-07-16 15:41:32,456 main DEBUG createLogger(additivity="null", level="INFO", name="org.mule", includeLocation="null", ={}, ={}, Configuration(sumologic), Filter=null)
2018-07-16 15:41:32,457 main DEBUG Building Plugin[name=asyncLogger, class=org.apache.logging.log4j.core.async.AsyncLoggerConfig].
2018-07-16 15:41:32,458 main DEBUG createLogger(additivity="null", level="INFO", name="com.mulesoft", includeLocation="null", ={}, ={}, Configuration(sumologic), Filter=null)
2018-07-16 15:41:32,459 main DEBUG Building Plugin[name=asyncLogger, class=org.apache.logging.log4j.core.async.AsyncLoggerConfig].
2018-07-16 15:41:32,462 main DEBUG createLogger(additivity="null", level="WARN", name="org.jetel", includeLocation="null", ={}, ={}, Configuration(sumologic), Filter=null)
2018-07-16 15:41:32,466 main DEBUG Building Plugin[name=asyncLogger, class=org.apache.logging.log4j.core.async.AsyncLoggerConfig].
2018-07-16 15:41:32,467 main DEBUG createLogger(additivity="null", level="WARN", name="Tracking", includeLocation="null", ={}, ={}, Configuration(sumologic), Filter=null)
2018-07-16 15:41:32,470 main DEBUG Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef].
2018-07-16 15:41:32,473 main DEBUG createAppenderRef(ref="Console", level="null", Filter=null)
2018-07-16 15:41:32,476 main DEBUG Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef].
2018-07-16 15:41:32,480 main DEBUG createAppenderRef(ref="SumoAppender", level="null", Filter=null)
2018-07-16 15:41:32,481 main DEBUG Building Plugin[name=asyncRoot, class=org.apache.logging.log4j.core.async.AsyncLoggerConfig$RootLogger].
2018-07-16 15:41:32,484 main DEBUG createLogger(additivity="null", level="INFO", includeLocation="null", ={Console, SumoAppender}, ={}, Configuration(sumologic), Filter=null)
2018-07-16 15:41:32,485 main DEBUG Building Plugin[name=loggers, class=org.apache.logging.log4j.core.config.LoggersPlugin].
2018-07-16 15:41:32,485 main DEBUG createLoggers(={org.apache.cxf, org.apache, org.springframework.beans.factory, org.mule, com.mulesoft, org.jetel, Tracking, root})
2018-07-16 15:41:32,498 main DEBUG Configuration XmlConfiguration[location=/home/vagrant/AnypointStudio/workspace-6-4/test-logging/target/test-classes/log4j2-test.xml] initialized
2018-07-16 15:41:32,506 main DEBUG Starting configuration XmlConfiguration[location=/home/vagrant/AnypointStudio/workspace-6-4/test-logging/target/test-classes/log4j2-test.xml]
2018-07-16 15:41:32,562 main DEBUG Starting AsyncLoggerConfig disruptor for this configuration with ringbufferSize=262144, waitStrategy=TimeoutBlockingWaitStrategy, exceptionHandler=org.apache.logging.log4j.core.async.AsyncLoggerConfigDefaultExceptionHandler@61dd1c3d...
2018-07-16 15:41:32,569 main DEBUG Started configuration XmlConfiguration[location=/home/vagrant/AnypointStudio/workspace-6-4/test-logging/target/test-classes/log4j2-test.xml] OK.
2018-07-16 15:41:32,571 main DEBUG Stopping SumoLogicAppender SumoAppender
2018-07-16 15:41:32,574 main DEBUG Mon Jul 16 15:41:32 AEST 2018 - Flushing and sending out 3 messages (0 messages left)
2018-07-16 15:41:32,575 main DEBUG Sending out data
peterc100 commented 6 years ago

here's with flushAllBeforeStopping="true" removed. the flow ends, i can see my psc>>>> messages in the console (unlike above).

but, oddly enough, i'm still not seeing anything at sumologic's end...

2018-07-16 16:14:12,918 main DEBUG createLogger(additivity="null", level="INFO", includeLocation="null", ={Console, SumoAppender}, ={}, Configuration(sumologic), Filter=null)
2018-07-16 16:14:12,918 main DEBUG Building Plugin[name=loggers, class=org.apache.logging.log4j.core.config.LoggersPlugin].
2018-07-16 16:14:12,919 main DEBUG createLoggers(={org.apache.cxf, org.apache, org.springframework.beans.factory, org.mule, com.mulesoft, org.jetel, Tracking, root})
2018-07-16 16:14:12,919 main DEBUG Configuration XmlConfiguration[location=/home/vagrant/AnypointStudio/workspace-6-4/test-logging/target/test-classes/log4j2-test.xml] initialized
2018-07-16 16:14:12,928 main DEBUG Starting configuration XmlConfiguration[location=/home/vagrant/AnypointStudio/workspace-6-4/test-logging/target/test-classes/log4j2-test.xml]
2018-07-16 16:14:12,934 main DEBUG Starting AsyncLoggerConfig disruptor for this configuration with ringbufferSize=262144, waitStrategy=TimeoutBlockingWaitStrategy, exceptionHandler=org.apache.logging.log4j.core.async.AsyncLoggerConfigDefaultExceptionHandler@61dd1c3d...
2018-07-16 16:14:12,935 main DEBUG Started configuration XmlConfiguration[location=/home/vagrant/AnypointStudio/workspace-6-4/test-logging/target/test-classes/log4j2-test.xml] OK.
2018-07-16 16:14:12,938 main DEBUG Stopping SumoLogicAppender SumoAppender
2018-07-16 16:14:12,947 main DEBUG flusher has been stopped
2018-07-16 16:14:12,948 main DEBUG SumoLogicAppender SumoAppender has been stopped
2018-07-16 16:14:12,948 main DEBUG Appender Console stopped with status true
2018-07-16 16:14:12,949 main DEBUG Stopped XmlConfiguration[location=/home/vagrant/AnypointStudio/workspace-6-4/test-logging/target/test-classes/log4j2-test.xml] OK
2018-07-16 16:14:12,955 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1
2018-07-16 16:14:12,956 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=StatusLogger
2018-07-16 16:14:12,965 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=ContextSelector
2018-07-16 16:14:12,972 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=
2018-07-16 16:14:12,973 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=,subtype=RingBuffer
2018-07-16 16:14:12,975 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=Tracking
2018-07-16 16:14:12,976 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=Tracking,subtype=RingBuffer
2018-07-16 16:14:12,984 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.apache.cxf
2018-07-16 16:14:13,000 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.apache.cxf,subtype=RingBuffer
2018-07-16 16:14:13,000 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.springframework.beans.factory
2018-07-16 16:14:13,001 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.springframework.beans.factory,subtype=RingBuffer
2018-07-16 16:14:13,001 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.mule
2018-07-16 16:14:13,002 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.mule,subtype=RingBuffer
2018-07-16 16:14:13,002 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.jetel
2018-07-16 16:14:13,002 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.jetel,subtype=RingBuffer
2018-07-16 16:14:13,004 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.apache
2018-07-16 16:14:13,005 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.apache,subtype=RingBuffer
2018-07-16 16:14:13,006 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=com.mulesoft
2018-07-16 16:14:13,007 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=com.mulesoft,subtype=RingBuffer
2018-07-16 16:14:13,007 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Appenders,name=Console
2018-07-16 16:14:13,009 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Appenders,name=SumoAppender
2018-07-16 16:14:13,009 main DEBUG Reconfiguration complete for context[name=5700d6b1] at URI /home/vagrant/AnypointStudio/workspace-6-4/test-logging/target/test-classes/log4j2-test.xml (org.apache.logging.log4j.core.LoggerContext@4b476233) with optional ClassLoader: null
INFO  2018-07-16 16:14:13,361 [main] org.mule.lifecycle.AbstractLifecycleManager: Initialising RegistryBroker
2018-07-16 16:14:13,361 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:13,361 +1000 [main] INFO  org.mule.lifecycle.AbstractLifecycleManager - Initialising RegistryBroker

INFO  2018-07-16 16:14:13,571 [main] org.mule.module.extension.internal.manager.DefaultExtensionManager: Starting discovery of extensions
2018-07-16 16:14:13,571 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:13,571 +1000 [main] INFO  org.mule.module.extension.internal.manager.DefaultExtensionManager - Starting discovery of extensions

INFO  2018-07-16 16:14:13,761 [main] org.mule.module.extension.internal.manager.DefaultExtensionManager: Discovered 1 extensions
2018-07-16 16:14:13,761 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:13,761 +1000 [main] INFO  org.mule.module.extension.internal.manager.DefaultExtensionManager - Discovered 1 extensions

INFO  2018-07-16 16:14:13,761 [main] org.mule.module.extension.internal.manager.DefaultExtensionManager: Registering extension validation (version 3.9)
2018-07-16 16:14:13,761 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:13,761 +1000 [main] INFO  org.mule.module.extension.internal.manager.DefaultExtensionManager - Registering extension validation (version 3.9)

INFO  2018-07-16 16:14:13,859 [main] org.mule.munit.runner.spring.config.MunitApplicationContext: Refreshing org.mule.munit.runner.spring.config.MunitApplicationContext@616f81b5: startup date [Mon Jul 16 16:14:13 AEST 2018]; root of context hierarchy
2018-07-16 16:14:13,859 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:13,859 +1000 [main] INFO  org.mule.munit.runner.spring.config.MunitApplicationContext - Refreshing org.mule.munit.runner.spring.config.MunitApplicationContext@616f81b5: startup date [Mon Jul 16 16:14:13 AEST 2018]; root of context hierarchy

INFO  2018-07-16 16:14:16,084 [main] org.mule.config.spring.processors.NoDevkitInjectorProcessor: JSR-330 'javax.inject.Inject' annotation found and supported for autowiring
2018-07-16 16:14:16,084 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:16,084 +1000 [main] INFO  org.mule.config.spring.processors.NoDevkitInjectorProcessor - JSR-330 'javax.inject.Inject' annotation found and supported for autowiring

WARN  2018-07-16 16:14:17,896 [main] org.mule.module.ognl.expression.OgnlExpressionEvaluator: OGNL module is deprecated and will be removed in Mule 4.0. Use MEL expressions instead.
2018-07-16 16:14:17,897 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:17,896 +1000 [main] WARN  org.mule.module.ognl.expression.OgnlExpressionEvaluator - OGNL module is deprecated and will be removed in Mule 4.0. Use MEL expressions instead.

INFO  2018-07-16 16:14:18,378 [main] org.mule.util.journal.TransactionJournal: Using files for tx logs /home/vagrant/AnypointStudio/workspace-6-4/test-logging/./.mule/queue-tx-log/tx1.log and /home/vagrant/AnypointStudio/workspace-6-4/test-logging/./.mule/queue-tx-log/tx2.log
2018-07-16 16:14:18,378 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:18,378 +1000 [main] INFO  org.mule.util.journal.TransactionJournal - Using files for tx logs /home/vagrant/AnypointStudio/workspace-6-4/test-logging/./.mule/queue-tx-log/tx1.log and /home/vagrant/AnypointStudio/workspace-6-4/test-logging/./.mule/queue-tx-log/tx2.log

INFO  2018-07-16 16:14:18,392 [main] org.mule.util.journal.TransactionJournal: Using files for tx logs /home/vagrant/AnypointStudio/workspace-6-4/test-logging/./.mule/queue-xa-tx-log/tx1.log and /home/vagrant/AnypointStudio/workspace-6-4/test-logging/./.mule/queue-xa-tx-log/tx2.log
2018-07-16 16:14:18,393 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:18,392 +1000 [main] INFO  org.mule.util.journal.TransactionJournal - Using files for tx logs /home/vagrant/AnypointStudio/workspace-6-4/test-logging/./.mule/queue-xa-tx-log/tx1.log and /home/vagrant/AnypointStudio/workspace-6-4/test-logging/./.mule/queue-xa-tx-log/tx2.log

INFO  2018-07-16 16:14:18,534 [main] org.mule.lifecycle.AbstractLifecycleManager: Initialising model: _muleSystemModel
2018-07-16 16:14:18,534 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:18,534 +1000 [main] INFO  org.mule.lifecycle.AbstractLifecycleManager - Initialising model: _muleSystemModel

INFO  2018-07-16 16:14:18,559 [main] org.mule.construct.FlowConstructLifecycleManager: Initialising flow: test-sumologic
2018-07-16 16:14:18,559 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:18,559 +1000 [main] INFO  org.mule.construct.FlowConstructLifecycleManager - Initialising flow: test-sumologic

INFO  2018-07-16 16:14:18,562 [main] org.mule.exception.DefaultMessagingExceptionStrategy: Initialising exception listener: org.mule.exception.DefaultMessagingExceptionStrategy@4f5df012
2018-07-16 16:14:18,562 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:18,562 +1000 [main] INFO  org.mule.exception.DefaultMessagingExceptionStrategy - Initialising exception listener: org.mule.exception.DefaultMessagingExceptionStrategy@4f5df012

INFO  2018-07-16 16:14:18,617 [main] org.mule.processor.SedaStageLifecycleManager: Initialising service: test-sumologic.stage1
2018-07-16 16:14:18,618 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:18,617 +1000 [main] INFO  org.mule.processor.SedaStageLifecycleManager - Initialising service: test-sumologic.stage1

INFO  2018-07-16 16:14:18,638 [main] org.mule.construct.FlowConstructLifecycleManager: Initialising flow: test-sumologic-by-logger-test
2018-07-16 16:14:18,638 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:18,638 +1000 [main] INFO  org.mule.construct.FlowConstructLifecycleManager - Initialising flow: test-sumologic-by-logger-test

INFO  2018-07-16 16:14:18,640 [main] org.mule.exception.DefaultMessagingExceptionStrategy: Initialising exception listener: org.mule.exception.DefaultMessagingExceptionStrategy@27e656e6
2018-07-16 16:14:18,641 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:18,640 +1000 [main] INFO  org.mule.exception.DefaultMessagingExceptionStrategy - Initialising exception listener: org.mule.exception.DefaultMessagingExceptionStrategy@27e656e6

INFO  2018-07-16 16:14:18,658 [main] org.mule.processor.SedaStageLifecycleManager: Initialising service: test-sumologic-by-logger-test.stage1
2018-07-16 16:14:18,658 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:18,658 +1000 [main] INFO  org.mule.processor.SedaStageLifecycleManager - Initialising service: test-sumologic-by-logger-test.stage1

INFO  2018-07-16 16:14:18,661 [main] org.mule.construct.FlowConstructLifecycleManager: Initialising flow: test-sumologic-by-groovy-test
2018-07-16 16:14:18,661 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:18,661 +1000 [main] INFO  org.mule.construct.FlowConstructLifecycleManager - Initialising flow: test-sumologic-by-groovy-test

INFO  2018-07-16 16:14:18,663 [main] org.mule.exception.DefaultMessagingExceptionStrategy: Initialising exception listener: org.mule.exception.DefaultMessagingExceptionStrategy@309d54ac
2018-07-16 16:14:18,663 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:18,663 +1000 [main] INFO  org.mule.exception.DefaultMessagingExceptionStrategy - Initialising exception listener: org.mule.exception.DefaultMessagingExceptionStrategy@309d54ac

INFO  2018-07-16 16:14:18,701 [main] org.mule.processor.SedaStageLifecycleManager: Initialising service: test-sumologic-by-groovy-test.stage1
2018-07-16 16:14:18,701 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:18,701 +1000 [main] INFO  org.mule.processor.SedaStageLifecycleManager - Initialising service: test-sumologic-by-groovy-test.stage1

INFO  2018-07-16 16:14:18,758 [main] org.mule.component.ComponentLifecycleManager: Initialising component: component.1714312592
2018-07-16 16:14:18,762 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:18,758 +1000 [main] INFO  org.mule.component.ComponentLifecycleManager - Initialising component: component.1714312592

INFO  2018-07-16 16:14:19,292 [main] org.mule.construct.FlowConstructLifecycleManager: Initialising flow: test-sumologic-by-http-test
2018-07-16 16:14:19,292 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:19,292 +1000 [main] INFO  org.mule.construct.FlowConstructLifecycleManager - Initialising flow: test-sumologic-by-http-test

INFO  2018-07-16 16:14:19,293 [main] org.mule.exception.DefaultMessagingExceptionStrategy: Initialising exception listener: org.mule.exception.DefaultMessagingExceptionStrategy@2ffaa711
2018-07-16 16:14:19,293 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:19,293 +1000 [main] INFO  org.mule.exception.DefaultMessagingExceptionStrategy - Initialising exception listener: org.mule.exception.DefaultMessagingExceptionStrategy@2ffaa711

INFO  2018-07-16 16:14:19,297 [main] org.mule.processor.SedaStageLifecycleManager: Initialising service: test-sumologic-by-http-test.stage1
2018-07-16 16:14:19,298 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:19,297 +1000 [main] INFO  org.mule.processor.SedaStageLifecycleManager - Initialising service: test-sumologic-by-http-test.stage1

WARN  2018-07-16 16:14:19,923 [main] org.mule.api.security.tls.TlsProperties: File tls-default.conf not found, using default configuration.
2018-07-16 16:14:19,923 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:19,923 +1000 [main] WARN  org.mule.api.security.tls.TlsProperties - File tls-default.conf not found, using default configuration.

INFO  2018-07-16 16:14:19,948 [main] org.mule.munit.runner.spring.config.MunitSpringXmlConfigurationBuilder: Configured Mule using "org.mule.munit.runner.spring.config.MunitSpringXmlConfigurationBuilder" with configuration resource(s): "[ConfigResource{resourceName='src/test/munit/test-sumologic-test-suite.xml'}]"
2018-07-16 16:14:19,949 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:19,948 +1000 [main] INFO  org.mule.munit.runner.spring.config.MunitSpringXmlConfigurationBuilder - Configured Mule using "org.mule.munit.runner.spring.config.MunitSpringXmlConfigurationBuilder" with configuration resource(s): "[ConfigResource{resourceName='src/test/munit/test-sumologic-test-suite.xml'}]"

INFO  2018-07-16 16:14:19,950 [main] org.mule.munit.runner.MuleContextManager: Loading application properties to Mule Context
2018-07-16 16:14:19,952 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:19,950 +1000 [main] INFO  org.mule.munit.runner.MuleContextManager - Loading application properties to Mule Context

INFO  2018-07-16 16:14:20,044 [main] org.mule.module.launcher.coreextension.DefaultMuleCoreExtensionManager: Initializing core extensions
2018-07-16 16:14:20,044 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:20,044 +1000 [main] INFO  org.mule.module.launcher.coreextension.DefaultMuleCoreExtensionManager - Initializing core extensions

INFO  2018-07-16 16:14:20,075 [main] org.mule.munit.plugins.coverage.CoberturaPlugin: Initialising coverage plugin...
2018-07-16 16:14:20,076 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:20,075 +1000 [main] INFO  org.mule.munit.plugins.coverage.CoberturaPlugin - Initialising coverage plugin...

INFO  2018-07-16 16:14:20,135 [main] org.mule.util.queue.QueueXaResourceManager: Starting ResourceManager
2018-07-16 16:14:20,136 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:20,135 +1000 [main] INFO  org.mule.util.queue.QueueXaResourceManager - Starting ResourceManager

INFO  2018-07-16 16:14:20,135 [main] org.mule.util.queue.QueueXaResourceManager: Started ResourceManager
2018-07-16 16:14:20,136 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:20,135 +1000 [main] INFO  org.mule.util.queue.QueueXaResourceManager - Started ResourceManager

INFO  2018-07-16 16:14:20,183 [main] au.com.deloitte.pe.utility.generated.agents.DefaultSplashScreenAgent: 
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
+ DevKit Extensions (0) used in this application 
                             +
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
2018-07-16 16:14:20,183 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:20,183 +1000 [main] INFO  au.com.deloitte.pe.utility.generated.agents.DefaultSplashScreenAgent - 
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
+ DevKit Extensions (0) used in this application 
                             +
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

INFO  2018-07-16 16:14:20,184 [main] org.mule.lifecycle.AbstractLifecycleManager: Starting model: _muleSystemModel
2018-07-16 16:14:20,186 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:20,184 +1000 [main] INFO  org.mule.lifecycle.AbstractLifecycleManager - Starting model: _muleSystemModel

INFO  2018-07-16 16:14:20,189 [main] org.mule.construct.FlowConstructLifecycleManager: Starting flow: test-sumologic
2018-07-16 16:14:20,195 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:20,189 +1000 [main] INFO  org.mule.construct.FlowConstructLifecycleManager - Starting flow: test-sumologic

INFO  2018-07-16 16:14:20,208 [main] org.mule.processor.SedaStageLifecycleManager: Starting service: test-sumologic.stage1
2018-07-16 16:14:20,209 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:20,208 +1000 [main] INFO  org.mule.processor.SedaStageLifecycleManager - Starting service: test-sumologic.stage1

INFO  2018-07-16 16:14:20,270 [main] org.mule.construct.FlowConstructLifecycleManager: Starting flow: test-sumologic-by-logger-test
2018-07-16 16:14:20,270 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:20,270 +1000 [main] INFO  org.mule.construct.FlowConstructLifecycleManager - Starting flow: test-sumologic-by-logger-test

INFO  2018-07-16 16:14:20,270 [main] org.mule.processor.SedaStageLifecycleManager: Starting service: test-sumologic-by-logger-test.stage1
2018-07-16 16:14:20,271 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:20,270 +1000 [main] INFO  org.mule.processor.SedaStageLifecycleManager - Starting service: test-sumologic-by-logger-test.stage1

INFO  2018-07-16 16:14:20,278 [main] org.mule.construct.FlowConstructLifecycleManager: Starting flow: test-sumologic-by-groovy-test
2018-07-16 16:14:20,279 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:20,278 +1000 [main] INFO  org.mule.construct.FlowConstructLifecycleManager - Starting flow: test-sumologic-by-groovy-test

INFO  2018-07-16 16:14:20,278 [main] org.mule.processor.SedaStageLifecycleManager: Starting service: test-sumologic-by-groovy-test.stage1
2018-07-16 16:14:20,279 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:20,278 +1000 [main] INFO  org.mule.processor.SedaStageLifecycleManager - Starting service: test-sumologic-by-groovy-test.stage1

INFO  2018-07-16 16:14:20,303 [main] org.mule.component.ComponentLifecycleManager: Starting component: component.1714312592
2018-07-16 16:14:20,304 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:20,303 +1000 [main] INFO  org.mule.component.ComponentLifecycleManager - Starting component: component.1714312592

INFO  2018-07-16 16:14:20,304 [main] org.mule.construct.FlowConstructLifecycleManager: Starting flow: test-sumologic-by-http-test
2018-07-16 16:14:20,304 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:20,304 +1000 [main] INFO  org.mule.construct.FlowConstructLifecycleManager - Starting flow: test-sumologic-by-http-test

INFO  2018-07-16 16:14:20,304 [main] org.mule.processor.SedaStageLifecycleManager: Starting service: test-sumologic-by-http-test.stage1
2018-07-16 16:14:20,304 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:20,304 +1000 [main] INFO  org.mule.processor.SedaStageLifecycleManager - Starting service: test-sumologic-by-http-test.stage1

INFO  2018-07-16 16:14:20,631 [main] org.mule.module.management.agent.WrapperManagerAgent: This JVM hasn't been launched by the wrapper, the agent will not run.
2018-07-16 16:14:20,632 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:20,631 +1000 [main] INFO  org.mule.module.management.agent.WrapperManagerAgent - This JVM hasn't been launched by the wrapper, the agent will not run.

INFO  2018-07-16 16:14:20,665 [main] org.mule.DefaultMuleContext: 
**********************************************************************
* Mule Runtime and Integration Platform                              *
* Version: 3.9.0 Build: d8737b4a                                     *
* MuleSoft, Inc.                                                     *
* For more information go to                                         *
* http://www.mulesoft.com/mule-esb-enterprise                        *
*                                                                    *
* Server started: 7/16/18 4:14 PM                                    *
* Server ID: 75ca6690-88bf-11e8-9fb2-0242abacb94c                    *
* JDK: 1.8.0_151 (mixed mode)                                        *
* OS encoding: UTF-8, Mule encoding: UTF-8                           *
* OS: Linux (4.4.0-127-generic, amd64)                               *
* Host: vm-rebecca (127.0.1.1)                                       *
*                                                                    *
* Agents Running:                                                    *
*   Batch module default engine                                      *
*   JMX Agent                                                        *
*   DevKit Extension Information                                     *
*   Wrapper Manager                                                  *
**********************************************************************
2018-07-16 16:14:20,665 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:20,665 +1000 [main] INFO  org.mule.DefaultMuleContext - 
**********************************************************************
* Mule Runtime and Integration Platform                              *
* Version: 3.9.0 Build: d8737b4a                                     *
* MuleSoft, Inc.                                                     *
* For more information go to                                         *
* http://www.mulesoft.com/mule-esb-enterprise                        *
*                                                                    *
* Server started: 7/16/18 4:14 PM                                    *
* Server ID: 75ca6690-88bf-11e8-9fb2-0242abacb94c                    *
* JDK: 1.8.0_151 (mixed mode)                                        *
* OS encoding: UTF-8, Mule encoding: UTF-8                           *
* OS: Linux (4.4.0-127-generic, amd64)                               *
* Host: vm-rebecca (127.0.1.1)                                       *
*                                                                    *
* Agents Running:                                                    *
*   Batch module default engine                                      *
*   JMX Agent                                                        *
*   DevKit Extension Information                                     *
*   Wrapper Manager                                                  *
**********************************************************************

INFO  2018-07-16 16:14:20,666 [main] org.mule.module.launcher.coreextension.DefaultMuleCoreExtensionManager: Starting core extensions
2018-07-16 16:14:20,667 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:20,666 +1000 [main] INFO  org.mule.module.launcher.coreextension.DefaultMuleCoreExtensionManager - Starting core extensions

=====================================================================
===========  Running  test-sumologic-test-suite.xml  test ===========
=====================================================================
Running test-sumologic-by-logger-test
INFO  2018-07-16 16:14:20,932 [main] /tmp/monkey/business-two: psc>>>> log-sumologic-by-logger-sub-start
2018-07-16 16:14:20,932 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:20,932 +1000 [main] INFO  /tmp/monkey/business-two - psc>>>> log-sumologic-by-logger-sub-start

INFO  2018-07-16 16:14:20,989 [main] /tmp/monkey/business-two: psc>>>> hello, world from mule!, using logger! log4j2.mule.test.var = 'hello-from-log4j2.mule.test.var-set-in-mule-app.properties'
2018-07-16 16:14:20,989 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:20,989 +1000 [main] INFO  /tmp/monkey/business-two - psc>>>> hello, world from mule!, using logger! log4j2.mule.test.var = 'hello-from-log4j2.mule.test.var-set-in-mule-app.properties'

INFO  2018-07-16 16:14:20,999 [main] /tmp/monkey/business-two: psc>>>> log-sumologic-by-logger-sub-end
2018-07-16 16:14:20,999 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:20,999 +1000 [main] INFO  /tmp/monkey/business-two - psc>>>> log-sumologic-by-logger-sub-end

SUCCESS - Test test-sumologic-by-logger-test finished Successfully.
INFO  2018-07-16 16:14:21,046 [main] org.mule.construct.FlowConstructLifecycleManager: Stopping flow: test-sumologic
2018-07-16 16:14:21,047 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:21,046 +1000 [main] INFO  org.mule.construct.FlowConstructLifecycleManager - Stopping flow: test-sumologic

INFO  2018-07-16 16:14:21,053 [main] org.mule.processor.SedaStageLifecycleManager: Stopping service: test-sumologic.stage1
2018-07-16 16:14:21,054 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:21,053 +1000 [main] INFO  org.mule.processor.SedaStageLifecycleManager - Stopping service: test-sumologic.stage1

INFO  2018-07-16 16:14:21,109 [main] org.mule.construct.FlowConstructLifecycleManager: Stopping flow: test-sumologic-by-logger-test
2018-07-16 16:14:21,109 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:21,109 +1000 [main] INFO  org.mule.construct.FlowConstructLifecycleManager - Stopping flow: test-sumologic-by-logger-test

INFO  2018-07-16 16:14:21,109 [main] org.mule.processor.SedaStageLifecycleManager: Stopping service: test-sumologic-by-logger-test.stage1
2018-07-16 16:14:21,110 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:21,109 +1000 [main] INFO  org.mule.processor.SedaStageLifecycleManager - Stopping service: test-sumologic-by-logger-test.stage1

INFO  2018-07-16 16:14:21,309 [main] org.mule.construct.FlowConstructLifecycleManager: Stopping flow: test-sumologic-by-groovy-test
2018-07-16 16:14:21,309 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:21,309 +1000 [main] INFO  org.mule.construct.FlowConstructLifecycleManager - Stopping flow: test-sumologic-by-groovy-test

INFO  2018-07-16 16:14:21,309 [main] org.mule.processor.SedaStageLifecycleManager: Stopping service: test-sumologic-by-groovy-test.stage1
2018-07-16 16:14:21,310 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:21,309 +1000 [main] INFO  org.mule.processor.SedaStageLifecycleManager - Stopping service: test-sumologic-by-groovy-test.stage1

INFO  2018-07-16 16:14:21,511 [main] org.mule.component.ComponentLifecycleManager: Stopping component: component.1714312592
2018-07-16 16:14:21,511 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:21,511 +1000 [main] INFO  org.mule.component.ComponentLifecycleManager - Stopping component: component.1714312592

INFO  2018-07-16 16:14:21,511 [main] org.mule.construct.FlowConstructLifecycleManager: Stopping flow: test-sumologic-by-http-test
2018-07-16 16:14:21,512 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:21,511 +1000 [main] INFO  org.mule.construct.FlowConstructLifecycleManager - Stopping flow: test-sumologic-by-http-test

INFO  2018-07-16 16:14:21,511 [main] org.mule.processor.SedaStageLifecycleManager: Stopping service: test-sumologic-by-http-test.stage1
2018-07-16 16:14:21,512 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:21,511 +1000 [main] INFO  org.mule.processor.SedaStageLifecycleManager - Stopping service: test-sumologic-by-http-test.stage1

INFO  2018-07-16 16:14:21,532 [main] org.mule.lifecycle.AbstractLifecycleManager: Stopping model: _muleSystemModel
2018-07-16 16:14:21,532 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:21,532 +1000 [main] INFO  org.mule.lifecycle.AbstractLifecycleManager - Stopping model: _muleSystemModel

INFO  2018-07-16 16:14:21,538 [main] org.mule.util.queue.QueueXaResourceManager: Stopping ResourceManager
2018-07-16 16:14:21,546 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:21,538 +1000 [main] INFO  org.mule.util.queue.QueueXaResourceManager - Stopping ResourceManager

INFO  2018-07-16 16:14:21,538 [main] org.mule.util.queue.QueueXaResourceManager: Stopped ResourceManager
2018-07-16 16:14:21,547 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:21,538 +1000 [main] INFO  org.mule.util.queue.QueueXaResourceManager - Stopped ResourceManager

INFO  2018-07-16 16:14:21,807 [Thread-2] org.mule.munit.plugins.coverage.server.MunitCoverageServer: Coverage connection received from localhost - true
2018-07-16 16:14:21,808 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:21,807 +1000 [Thread-2] INFO  org.mule.munit.plugins.coverage.server.MunitCoverageServer - Coverage connection received from localhost - true

Connected to localhost in port 50792
INFO  2018-07-16 16:14:21,829 [main] org.mule.lifecycle.AbstractLifecycleManager: Disposing RegistryBroker
2018-07-16 16:14:21,830 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:21,829 +1000 [main] INFO  org.mule.lifecycle.AbstractLifecycleManager - Disposing RegistryBroker

INFO  2018-07-16 16:14:21,831 [main] org.mule.construct.FlowConstructLifecycleManager: Disposing flow: test-sumologic
2018-07-16 16:14:21,832 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:21,831 +1000 [main] INFO  org.mule.construct.FlowConstructLifecycleManager - Disposing flow: test-sumologic

INFO  2018-07-16 16:14:21,831 [main] org.mule.processor.SedaStageLifecycleManager: Disposing service: test-sumologic.stage1
2018-07-16 16:14:21,832 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:21,831 +1000 [main] INFO  org.mule.processor.SedaStageLifecycleManager - Disposing service: test-sumologic.stage1

INFO  2018-07-16 16:14:21,831 [main] org.mule.construct.FlowConstructLifecycleManager: Disposing flow: test-sumologic-by-logger-test
2018-07-16 16:14:21,832 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:21,831 +1000 [main] INFO  org.mule.construct.FlowConstructLifecycleManager - Disposing flow: test-sumologic-by-logger-test

INFO  2018-07-16 16:14:21,831 [main] org.mule.processor.SedaStageLifecycleManager: Disposing service: test-sumologic-by-logger-test.stage1
2018-07-16 16:14:21,832 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:21,831 +1000 [main] INFO  org.mule.processor.SedaStageLifecycleManager - Disposing service: test-sumologic-by-logger-test.stage1

INFO  2018-07-16 16:14:21,831 [main] org.mule.construct.FlowConstructLifecycleManager: Disposing flow: test-sumologic-by-groovy-test
2018-07-16 16:14:21,832 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:21,831 +1000 [main] INFO  org.mule.construct.FlowConstructLifecycleManager - Disposing flow: test-sumologic-by-groovy-test

INFO  2018-07-16 16:14:21,831 [main] org.mule.processor.SedaStageLifecycleManager: Disposing service: test-sumologic-by-groovy-test.stage1
2018-07-16 16:14:21,832 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:21,831 +1000 [main] INFO  org.mule.processor.SedaStageLifecycleManager - Disposing service: test-sumologic-by-groovy-test.stage1

INFO  2018-07-16 16:14:21,832 [main] org.mule.component.ComponentLifecycleManager: Disposing component: component.1714312592
2018-07-16 16:14:21,834 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:21,832 +1000 [main] INFO  org.mule.component.ComponentLifecycleManager - Disposing component: component.1714312592

INFO  2018-07-16 16:14:21,833 [main] org.mule.construct.FlowConstructLifecycleManager: Disposing flow: test-sumologic-by-http-test
2018-07-16 16:14:21,834 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:21,833 +1000 [main] INFO  org.mule.construct.FlowConstructLifecycleManager - Disposing flow: test-sumologic-by-http-test

INFO  2018-07-16 16:14:21,833 [main] org.mule.processor.SedaStageLifecycleManager: Disposing service: test-sumologic-by-http-test.stage1
2018-07-16 16:14:21,834 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:21,833 +1000 [main] INFO  org.mule.processor.SedaStageLifecycleManager - Disposing service: test-sumologic-by-http-test.stage1

INFO  2018-07-16 16:14:21,834 [main] org.mule.lifecycle.AbstractLifecycleManager: Disposing model: _muleSystemModel
2018-07-16 16:14:21,834 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:21,834 +1000 [main] INFO  org.mule.lifecycle.AbstractLifecycleManager - Disposing model: _muleSystemModel

[org.mule.munit.remote.CoverageManager]accumulating report
[org.mule.munit.remote.CoverageManager]report is not null
INFO  2018-07-16 16:14:21,857 [Thread-2] org.mule.munit.plugins.coverage.server.MunitCoverageServer: Waiting for coverage connection 
2018-07-16 16:14:21,857 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:21,857 +1000 [Thread-2] INFO  org.mule.munit.plugins.coverage.server.MunitCoverageServer - Waiting for coverage connection 

INFO  2018-07-16 16:14:22,122 [main] org.mule.munit.runner.spring.config.MunitApplicationContext: Closing org.mule.munit.runner.spring.config.MunitApplicationContext@616f81b5: startup date [Mon Jul 16 16:14:13 AEST 2018]; root of context hierarchy
2018-07-16 16:14:22,123 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:22,122 +1000 [main] INFO  org.mule.munit.runner.spring.config.MunitApplicationContext - Closing org.mule.munit.runner.spring.config.MunitApplicationContext@616f81b5: startup date [Mon Jul 16 16:14:13 AEST 2018]; root of context hierarchy

INFO  2018-07-16 16:14:22,133 [main] org.mule.DefaultMuleContext: 
**********************************************************************
* Mule Context shut down normally on: 7/16/18 4:14 PM                *
* Server was up for: 0 days, 0 hours, 0 mins, 1.996 sec              *
**********************************************************************
2018-07-16 16:14:22,133 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:22,133 +1000 [main] INFO  org.mule.DefaultMuleContext - 
**********************************************************************
* Mule Context shut down normally on: 7/16/18 4:14 PM                *
* Server was up for: 0 days, 0 hours, 0 mins, 1.996 sec              *
**********************************************************************

===================================================================================
Number of tests run: 1 - Failed: 0 - Errors: 0 - Skipped: 0 - Time elapsed: 0.333ms
===================================================================================
[org.mule.munit.remote.CoverageManager]Calculating application coverage for resources: config.xml,test-sumologic.xml
INFO  2018-07-16 16:14:22,152 [main] org.mule.munit.runner.MuleContextManager: Loading mule-app.properties ...
2018-07-16 16:14:22,152 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:22,152 +1000 [main] INFO  org.mule.munit.runner.MuleContextManager - Loading mule-app.properties ...

2018-07-16 16:14:22,155 main DEBUG Reconfiguration started for context[name=5700d6b1] at URI null (org.apache.logging.log4j.core.LoggerContext@4b476233) with optional ClassLoader: null
2018-07-16 16:14:22,155 main DEBUG Using configurationFactory org.apache.logging.log4j.core.config.ConfigurationFactory$Factory@2e1add6f
INFO  2018-07-16 16:14:22,154 [main] org.mule.munit.runner.domain.MunitDomainContextBuilder: Loading mule-deploy.properties ...
2018-07-16 16:14:22,156 Log4j2-TF-1-AsyncLoggerConfig-2 DEBUG Sending messge to Sumo: 2018-07-16 16:14:22,154 +1000 [main] INFO  org.mule.munit.runner.domain.MunitDomainContextBuilder - Loading mule-deploy.properties ...

2018-07-16 16:14:22,157 main INFO Log4j appears to be running in a Servlet environment, but there's no log4j-web module available. If you want better web container support, please add the log4j-web JAR to your web archive or server lib directory.
2018-07-16 16:14:22,163 main DEBUG Initializing configuration XmlConfiguration[location=/home/vagrant/AnypointStudio/workspace-6-4/test-logging/target/test-classes/log4j2-test.xml]
2018-07-16 16:14:22,166 main DEBUG Installed script engines
2018-07-16 16:14:22,167 main DEBUG Groovy Scripting Engine Version: 2.0, Language: Groovy, Threading: MULTITHREADED, Compile: true, Names: {groovy, Groovy}
2018-07-16 16:14:22,868 SumoBufferFlusherThread DEBUG Mon Jul 16 16:14:22 AEST 2018 - Flushing and sending out 76 messages (0 messages left)
2018-07-16 16:14:22,868 SumoBufferFlusherThread DEBUG Sending out data
2018-07-16 16:14:23,000 main DEBUG jython Version: 2.7.3, Language: python, Threading: MULTITHREADED, Compile: true, Names: {python, jython}
2018-07-16 16:14:23,026 main DEBUG Scala Interpreter Version: 1.0, Language: Scala, Threading: Not Thread Safe, Compile: true, Names: {scala}
2018-07-16 16:14:23,038 main DEBUG Mozilla Rhino Version: 1.6R5, Language: ECMAScript, Threading: MULTITHREADED, Compile: true, Names: {rhino-nonjdk, js, rhino, JavaScript, javascript, ECMAScript, ecmascript}
2018-07-16 16:14:23,057 main DEBUG Mozilla Rhino Version: 1.6 release 2, Language: EmbeddedECMAScript, Threading: MULTITHREADED, Compile: true, Names: {ejs, EmbeddedJavaScript, embeddedjavascript}
2018-07-16 16:14:23,082 main DEBUG JSR 223 JRuby Engine Version: 1.7.27, Language: ruby, Threading: THREAD-ISOLATED, Compile: true, Names: {ruby, jruby}
2018-07-16 16:14:23,102 main DEBUG Oracle Nashorn Version: 1.8.0_151, Language: ECMAScript, Threading: Not Thread Safe, Compile: true, Names: {nashorn, Nashorn, js, JS, JavaScript, javascript, ECMAScript, ecmascript}
2018-07-16 16:14:23,105 main DEBUG PluginManager 'Core' found 113 plugins
2018-07-16 16:14:23,116 main DEBUG PluginManager 'Level' found 0 plugins
2018-07-16 16:14:23,119 main DEBUG PluginManager 'Lookup' found 13 plugins
2018-07-16 16:14:23,119 main DEBUG Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout].
2018-07-16 16:14:23,120 main DEBUG PatternLayout$Builder(pattern="%-5p %d [%t] %c: %m%n", PatternSelector=null, Configuration(sumologic), Replace=null, charset="null", alwaysWriteExceptions="null", disableAnsi="null", noConsoleNoAnsi="null", header="null", footer="null")
2018-07-16 16:14:23,121 main DEBUG PluginManager 'Converter' found 41 plugins
2018-07-16 16:14:23,131 main DEBUG Building Plugin[name=appender, class=org.apache.logging.log4j.core.appender.ConsoleAppender].
2018-07-16 16:14:23,144 main DEBUG ConsoleAppender$Builder(target="SYSTEM_OUT", follow="null", direct="null", bufferedIo="null", bufferSize="null", immediateFlush="null", ignoreExceptions="null", PatternLayout(%-5p %d [%t] %c: %m%n), name="Console", Configuration(sumologic), Filter=null)
2018-07-16 16:14:23,145 main DEBUG Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout].
2018-07-16 16:14:23,145 main DEBUG PatternLayout$Builder(pattern="%d{yyyy-MM-dd HH:mm:ss,SSS Z} [%t] %-5p %c - %m%n", PatternSelector=null, Configuration(sumologic), Replace=null, charset="null", alwaysWriteExceptions="null", disableAnsi="null", noConsoleNoAnsi="null", header="null", footer="null")
2018-07-16 16:14:23,145 main DEBUG Building Plugin[name=appender, class=com.sumologic.log4j.SumoLogicAppender].
2018-07-16 16:14:23,147 main DEBUG createAppender(name="SumoAppender", PatternLayout(%d{yyyy-MM-dd HH:mm:ss,SSS Z} [%t] %-5p %c - %m%n), Filter=null, url="https://collectors.au.sumologic.com/receiver/v1/http/ZaVnC4dhaV3VUtT1kQx8VtT0XTyBSnmeVHv8ZsTDNCZN9Ol6zc9Dao5UvKzhbmMniVTXXKEcWN7cQJLLepbk3adJxz84dm7c8Fl9s8T-2ldvNeFY28MgGA==", proxyAuth="null", proxyHost="null", proxyPort="0", proxyUser="null", proxyPassword="null", proxyDomain="null", retryInterval="10000", connectionTimeout="1000", socketTimeout="60000", messagesPerRequest="100", maxFlushInterval="10000", sourceName="null", sourceCategory="null", sourceHost="null", flushingAccuracy="250", maxQueueSizeBytes="1000000", flushAllBeforeStopping="false")
2018-07-16 16:14:23,196 main DEBUG Building Plugin[name=appenders, class=org.apache.logging.log4j.core.config.AppendersPlugin].
2018-07-16 16:14:23,198 main DEBUG createAppenders(={Console, SumoAppender})
2018-07-16 16:14:23,199 main DEBUG Building Plugin[name=asyncLogger, class=org.apache.logging.log4j.core.async.AsyncLoggerConfig].
2018-07-16 16:14:23,201 main DEBUG createLogger(additivity="null", level="WARN", name="org.apache.cxf", includeLocation="null", ={}, ={}, Configuration(sumologic), Filter=null)
2018-07-16 16:14:23,201 main DEBUG Building Plugin[name=asyncLogger, class=org.apache.logging.log4j.core.async.AsyncLoggerConfig].
2018-07-16 16:14:23,202 main DEBUG createLogger(additivity="null", level="WARN", name="org.apache", includeLocation="null", ={}, ={}, Configuration(sumologic), Filter=null)
2018-07-16 16:14:23,202 main DEBUG Building Plugin[name=asyncLogger, class=org.apache.logging.log4j.core.async.AsyncLoggerConfig].
2018-07-16 16:14:23,203 main DEBUG createLogger(additivity="null", level="WARN", name="org.springframework.beans.factory", includeLocation="null", ={}, ={}, Configuration(sumologic), Filter=null)
2018-07-16 16:14:23,203 main DEBUG Building Plugin[name=asyncLogger, class=org.apache.logging.log4j.core.async.AsyncLoggerConfig].
2018-07-16 16:14:23,204 main DEBUG createLogger(additivity="null", level="INFO", name="org.mule", includeLocation="null", ={}, ={}, Configuration(sumologic), Filter=null)
2018-07-16 16:14:23,212 main DEBUG Building Plugin[name=asyncLogger, class=org.apache.logging.log4j.core.async.AsyncLoggerConfig].
2018-07-16 16:14:23,215 main DEBUG createLogger(additivity="null", level="INFO", name="com.mulesoft", includeLocation="null", ={}, ={}, Configuration(sumologic), Filter=null)
2018-07-16 16:14:23,216 main DEBUG Building Plugin[name=asyncLogger, class=org.apache.logging.log4j.core.async.AsyncLoggerConfig].
2018-07-16 16:14:23,218 main DEBUG createLogger(additivity="null", level="WARN", name="org.jetel", includeLocation="null", ={}, ={}, Configuration(sumologic), Filter=null)
2018-07-16 16:14:23,218 main DEBUG Building Plugin[name=asyncLogger, class=org.apache.logging.log4j.core.async.AsyncLoggerConfig].
2018-07-16 16:14:23,218 main DEBUG createLogger(additivity="null", level="WARN", name="Tracking", includeLocation="null", ={}, ={}, Configuration(sumologic), Filter=null)
2018-07-16 16:14:23,219 main DEBUG Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef].
2018-07-16 16:14:23,219 main DEBUG createAppenderRef(ref="Console", level="null", Filter=null)
2018-07-16 16:14:23,219 main DEBUG Building Plugin[name=AppenderRef, class=org.apache.logging.log4j.core.config.AppenderRef].
2018-07-16 16:14:23,219 main DEBUG createAppenderRef(ref="SumoAppender", level="null", Filter=null)
2018-07-16 16:14:23,219 main DEBUG Building Plugin[name=asyncRoot, class=org.apache.logging.log4j.core.async.AsyncLoggerConfig$RootLogger].
2018-07-16 16:14:23,219 main DEBUG createLogger(additivity="null", level="INFO", includeLocation="null", ={Console, SumoAppender}, ={}, Configuration(sumologic), Filter=null)
2018-07-16 16:14:23,220 main DEBUG Building Plugin[name=loggers, class=org.apache.logging.log4j.core.config.LoggersPlugin].
2018-07-16 16:14:23,220 main DEBUG createLoggers(={org.apache.cxf, org.apache, org.springframework.beans.factory, org.mule, com.mulesoft, org.jetel, Tracking, root})
2018-07-16 16:14:23,220 main DEBUG Configuration XmlConfiguration[location=/home/vagrant/AnypointStudio/workspace-6-4/test-logging/target/test-classes/log4j2-test.xml] initialized
2018-07-16 16:14:23,220 main DEBUG Starting configuration XmlConfiguration[location=/home/vagrant/AnypointStudio/workspace-6-4/test-logging/target/test-classes/log4j2-test.xml]
2018-07-16 16:14:23,243 main DEBUG Starting AsyncLoggerConfig disruptor for this configuration with ringbufferSize=262144, waitStrategy=TimeoutBlockingWaitStrategy, exceptionHandler=org.apache.logging.log4j.core.async.AsyncLoggerConfigDefaultExceptionHandler@7ec01440...
2018-07-16 16:14:23,247 main DEBUG Started configuration XmlConfiguration[location=/home/vagrant/AnypointStudio/workspace-6-4/test-logging/target/test-classes/log4j2-test.xml] OK.
2018-07-16 16:14:23,286 main DEBUG Stopping SumoLogicAppender SumoAppender
2018-07-16 16:14:23,286 main DEBUG flusher has been stopped
2018-07-16 16:14:23,290 main DEBUG SumoLogicAppender SumoAppender has been stopped
2018-07-16 16:14:23,290 main DEBUG Appender Console stopped with status true
2018-07-16 16:14:23,291 main DEBUG Stopped XmlConfiguration[location=/home/vagrant/AnypointStudio/workspace-6-4/test-logging/target/test-classes/log4j2-test.xml] OK
2018-07-16 16:14:23,292 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1
2018-07-16 16:14:23,294 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=StatusLogger
2018-07-16 16:14:23,298 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=ContextSelector
2018-07-16 16:14:23,298 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=
2018-07-16 16:14:23,298 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=,subtype=RingBuffer
2018-07-16 16:14:23,299 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=Tracking
2018-07-16 16:14:23,301 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=Tracking,subtype=RingBuffer
2018-07-16 16:14:23,304 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.apache.cxf
2018-07-16 16:14:23,316 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.apache.cxf,subtype=RingBuffer
2018-07-16 16:14:23,320 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.springframework.beans.factory
2018-07-16 16:14:23,321 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.springframework.beans.factory,subtype=RingBuffer
2018-07-16 16:14:23,321 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.mule
2018-07-16 16:14:23,322 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.mule,subtype=RingBuffer
2018-07-16 16:14:23,322 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.jetel
2018-07-16 16:14:23,323 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.jetel,subtype=RingBuffer
2018-07-16 16:14:23,326 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.apache
2018-07-16 16:14:23,339 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=org.apache,subtype=RingBuffer
2018-07-16 16:14:23,340 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=com.mulesoft
2018-07-16 16:14:23,340 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Loggers,name=com.mulesoft,subtype=RingBuffer
2018-07-16 16:14:23,352 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Appenders,name=Console
2018-07-16 16:14:23,353 main DEBUG Registering MBean org.apache.logging.log4j2:type=5700d6b1,component=Appenders,name=SumoAppender
2018-07-16 16:14:23,353 main DEBUG Reconfiguration complete for context[name=5700d6b1] at URI /home/vagrant/AnypointStudio/workspace-6-4/test-logging/target/test-classes/log4j2-test.xml (org.apache.logging.log4j.core.LoggerContext@4b476233) with optional ClassLoader: null
INFO  2018-07-16 16:14:23,411 [main] org.mule.lifecycle.AbstractLifecycleManager: Initialising RegistryBroker
2018-07-16 16:14:23,412 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:23,411 +1000 [main] INFO  org.mule.lifecycle.AbstractLifecycleManager - Initialising RegistryBroker

INFO  2018-07-16 16:14:23,442 [main] org.mule.module.extension.internal.manager.DefaultExtensionManager: Starting discovery of extensions
2018-07-16 16:14:23,443 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:23,442 +1000 [main] INFO  org.mule.module.extension.internal.manager.DefaultExtensionManager - Starting discovery of extensions

INFO  2018-07-16 16:14:23,504 [main] org.mule.module.extension.internal.manager.DefaultExtensionManager: Discovered 1 extensions
2018-07-16 16:14:23,505 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:23,504 +1000 [main] INFO  org.mule.module.extension.internal.manager.DefaultExtensionManager - Discovered 1 extensions

INFO  2018-07-16 16:14:23,505 [main] org.mule.module.extension.internal.manager.DefaultExtensionManager: Registering extension validation (version 3.9)
2018-07-16 16:14:23,505 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:23,505 +1000 [main] INFO  org.mule.module.extension.internal.manager.DefaultExtensionManager - Registering extension validation (version 3.9)

INFO  2018-07-16 16:14:23,510 [main] org.mule.munit.runner.spring.config.MunitApplicationContext: Refreshing org.mule.munit.runner.spring.config.MunitApplicationContext@30fffb53: startup date [Mon Jul 16 16:14:23 AEST 2018]; root of context hierarchy
2018-07-16 16:14:23,510 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:23,510 +1000 [main] INFO  org.mule.munit.runner.spring.config.MunitApplicationContext - Refreshing org.mule.munit.runner.spring.config.MunitApplicationContext@30fffb53: startup date [Mon Jul 16 16:14:23 AEST 2018]; root of context hierarchy

INFO  2018-07-16 16:14:23,991 [main] org.mule.config.spring.processors.NoDevkitInjectorProcessor: JSR-330 'javax.inject.Inject' annotation found and supported for autowiring
2018-07-16 16:14:23,991 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:23,991 +1000 [main] INFO  org.mule.config.spring.processors.NoDevkitInjectorProcessor - JSR-330 'javax.inject.Inject' annotation found and supported for autowiring

INFO  2018-07-16 16:14:24,367 [main] org.mule.util.journal.TransactionJournal: Using files for tx logs /home/vagrant/AnypointStudio/workspace-6-4/test-logging/./.mule/queue-tx-log/tx1.log and /home/vagrant/AnypointStudio/workspace-6-4/test-logging/./.mule/queue-tx-log/tx2.log
2018-07-16 16:14:24,368 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,367 +1000 [main] INFO  org.mule.util.journal.TransactionJournal - Using files for tx logs /home/vagrant/AnypointStudio/workspace-6-4/test-logging/./.mule/queue-tx-log/tx1.log and /home/vagrant/AnypointStudio/workspace-6-4/test-logging/./.mule/queue-tx-log/tx2.log

INFO  2018-07-16 16:14:24,380 [main] org.mule.util.journal.TransactionJournal: Using files for tx logs /home/vagrant/AnypointStudio/workspace-6-4/test-logging/./.mule/queue-xa-tx-log/tx1.log and /home/vagrant/AnypointStudio/workspace-6-4/test-logging/./.mule/queue-xa-tx-log/tx2.log
2018-07-16 16:14:24,381 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,380 +1000 [main] INFO  org.mule.util.journal.TransactionJournal - Using files for tx logs /home/vagrant/AnypointStudio/workspace-6-4/test-logging/./.mule/queue-xa-tx-log/tx1.log and /home/vagrant/AnypointStudio/workspace-6-4/test-logging/./.mule/queue-xa-tx-log/tx2.log

INFO  2018-07-16 16:14:24,393 [main] org.mule.lifecycle.AbstractLifecycleManager: Initialising connector: connector.polling.mule.default
2018-07-16 16:14:24,393 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,393 +1000 [main] INFO  org.mule.lifecycle.AbstractLifecycleManager - Initialising connector: connector.polling.mule.default

INFO  2018-07-16 16:14:24,446 [main] org.mule.lifecycle.AbstractLifecycleManager: Initialising model: _muleSystemModel
2018-07-16 16:14:24,446 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,446 +1000 [main] INFO  org.mule.lifecycle.AbstractLifecycleManager - Initialising model: _muleSystemModel

INFO  2018-07-16 16:14:24,452 [main] org.mule.construct.FlowConstructLifecycleManager: Initialising flow: test-sumologic
2018-07-16 16:14:24,452 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,452 +1000 [main] INFO  org.mule.construct.FlowConstructLifecycleManager - Initialising flow: test-sumologic

INFO  2018-07-16 16:14:24,452 [main] org.mule.exception.DefaultMessagingExceptionStrategy: Initialising exception listener: org.mule.exception.DefaultMessagingExceptionStrategy@28806954
2018-07-16 16:14:24,452 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,452 +1000 [main] INFO  org.mule.exception.DefaultMessagingExceptionStrategy - Initialising exception listener: org.mule.exception.DefaultMessagingExceptionStrategy@28806954

INFO  2018-07-16 16:14:24,460 [main] org.mule.processor.SedaStageLifecycleManager: Initialising service: test-sumologic.stage1
2018-07-16 16:14:24,461 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,460 +1000 [main] INFO  org.mule.processor.SedaStageLifecycleManager - Initialising service: test-sumologic.stage1

WARN  2018-07-16 16:14:24,535 [main] org.mule.api.security.tls.TlsProperties: File tls-default.conf not found, using default configuration.
2018-07-16 16:14:24,536 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,535 +1000 [main] WARN  org.mule.api.security.tls.TlsProperties - File tls-default.conf not found, using default configuration.

INFO  2018-07-16 16:14:24,545 [main] org.mule.munit.runner.spring.config.MunitSpringXmlConfigurationBuilder: Configured Mule using "org.mule.munit.runner.spring.config.MunitSpringXmlConfigurationBuilder" with configuration resource(s): "[ConfigResource{resourceName='config.xml'}, ConfigResource{resourceName='test-sumologic.xml'}]"
2018-07-16 16:14:24,546 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,545 +1000 [main] INFO  org.mule.munit.runner.spring.config.MunitSpringXmlConfigurationBuilder - Configured Mule using "org.mule.munit.runner.spring.config.MunitSpringXmlConfigurationBuilder" with configuration resource(s): "[ConfigResource{resourceName='config.xml'}, ConfigResource{resourceName='test-sumologic.xml'}]"

INFO  2018-07-16 16:14:24,545 [main] org.mule.munit.runner.MuleContextManager: Loading application properties to Mule Context
2018-07-16 16:14:24,548 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,545 +1000 [main] INFO  org.mule.munit.runner.MuleContextManager - Loading application properties to Mule Context

INFO  2018-07-16 16:14:24,553 [main] org.mule.module.launcher.coreextension.DefaultMuleCoreExtensionManager: Initializing core extensions
2018-07-16 16:14:24,553 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,553 +1000 [main] INFO  org.mule.module.launcher.coreextension.DefaultMuleCoreExtensionManager - Initializing core extensions

INFO  2018-07-16 16:14:24,553 [main] org.mule.munit.plugins.coverage.CoberturaPlugin: Initialising coverage plugin...
2018-07-16 16:14:24,553 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,553 +1000 [main] INFO  org.mule.munit.plugins.coverage.CoberturaPlugin - Initialising coverage plugin...

INFO  2018-07-16 16:14:24,562 [main] org.mule.util.queue.QueueXaResourceManager: Starting ResourceManager
2018-07-16 16:14:24,562 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,562 +1000 [main] INFO  org.mule.util.queue.QueueXaResourceManager - Starting ResourceManager

INFO  2018-07-16 16:14:24,562 [main] org.mule.util.queue.QueueXaResourceManager: Started ResourceManager
2018-07-16 16:14:24,570 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,562 +1000 [main] INFO  org.mule.util.queue.QueueXaResourceManager - Started ResourceManager

INFO  2018-07-16 16:14:24,588 [main] org.mule.transport.polling.MessageProcessorPollingConnector: Connected: MessageProcessorPollingConnector
{
  name=connector.polling.mule.default
  lifecycle=initialise
  this=17c7cc93
  numberOfConcurrentTransactedReceivers=4
  createMultipleTransactedReceivers=true
  connected=true
  supportedProtocols=[polling]
  serviceOverrides=<none>
}

2018-07-16 16:14:24,588 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,588 +1000 [main] INFO  org.mule.transport.polling.MessageProcessorPollingConnector - Connected: MessageProcessorPollingConnector
{
  name=connector.polling.mule.default
  lifecycle=initialise
  this=17c7cc93
  numberOfConcurrentTransactedReceivers=4
  createMultipleTransactedReceivers=true
  connected=true
  supportedProtocols=[polling]
  serviceOverrides=<none>
}

INFO  2018-07-16 16:14:24,588 [main] org.mule.transport.polling.MessageProcessorPollingConnector: Starting: MessageProcessorPollingConnector
{
  name=connector.polling.mule.default
  lifecycle=initialise
  this=17c7cc93
  numberOfConcurrentTransactedReceivers=4
  createMultipleTransactedReceivers=true
  connected=true
  supportedProtocols=[polling]
  serviceOverrides=<none>
}

2018-07-16 16:14:24,589 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,588 +1000 [main] INFO  org.mule.transport.polling.MessageProcessorPollingConnector - Starting: MessageProcessorPollingConnector
{
  name=connector.polling.mule.default
  lifecycle=initialise
  this=17c7cc93
  numberOfConcurrentTransactedReceivers=4
  createMultipleTransactedReceivers=true
  connected=true
  supportedProtocols=[polling]
  serviceOverrides=<none>
}

INFO  2018-07-16 16:14:24,607 [main] org.mule.lifecycle.AbstractLifecycleManager: Starting connector: connector.polling.mule.default
2018-07-16 16:14:24,612 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,607 +1000 [main] INFO  org.mule.lifecycle.AbstractLifecycleManager - Starting connector: connector.polling.mule.default

INFO  2018-07-16 16:14:24,632 [main] au.com.deloitte.pe.utility.generated.agents.DefaultSplashScreenAgent: 
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
+ DevKit Extensions (0) used in this application 
                             +
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
2018-07-16 16:14:24,633 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,632 +1000 [main] INFO  au.com.deloitte.pe.utility.generated.agents.DefaultSplashScreenAgent - 
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
+ DevKit Extensions (0) used in this application 
                             +
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

INFO  2018-07-16 16:14:24,634 [main] org.mule.lifecycle.AbstractLifecycleManager: Starting model: _muleSystemModel
2018-07-16 16:14:24,635 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,634 +1000 [main] INFO  org.mule.lifecycle.AbstractLifecycleManager - Starting model: _muleSystemModel

INFO  2018-07-16 16:14:24,648 [main] org.mule.construct.FlowConstructLifecycleManager: Starting flow: test-sumologic
2018-07-16 16:14:24,649 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,648 +1000 [main] INFO  org.mule.construct.FlowConstructLifecycleManager - Starting flow: test-sumologic

INFO  2018-07-16 16:14:24,648 [main] org.mule.processor.SedaStageLifecycleManager: Starting service: test-sumologic.stage1
2018-07-16 16:14:24,649 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,648 +1000 [main] INFO  org.mule.processor.SedaStageLifecycleManager - Starting service: test-sumologic.stage1

INFO  2018-07-16 16:14:24,719 [main] org.mule.transport.polling.MessageProcessorPollingConnector: Registering listener: test-sumologic on endpointUri: polling://-1912630717
2018-07-16 16:14:24,719 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,719 +1000 [main] INFO  org.mule.transport.polling.MessageProcessorPollingConnector - Registering listener: test-sumologic on endpointUri: polling://-1912630717

INFO  2018-07-16 16:14:24,763 [main] org.mule.lifecycle.AbstractLifecycleManager: Initialising: 'null'. Object is: MessageProcessorPollingMessageReceiver
2018-07-16 16:14:24,763 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,763 +1000 [main] INFO  org.mule.lifecycle.AbstractLifecycleManager - Initialising: 'null'. Object is: MessageProcessorPollingMessageReceiver

INFO  2018-07-16 16:14:24,805 [main] org.mule.lifecycle.AbstractLifecycleManager: Initialising Bean: polling://test-sumologic/1343134043
2018-07-16 16:14:24,806 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,805 +1000 [main] INFO  org.mule.lifecycle.AbstractLifecycleManager - Initialising Bean: polling://test-sumologic/1343134043

INFO  2018-07-16 16:14:24,809 [main] org.mule.lifecycle.AbstractLifecycleManager: Starting Bean: polling://test-sumologic/1343134043
2018-07-16 16:14:24,809 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,809 +1000 [main] INFO  org.mule.lifecycle.AbstractLifecycleManager - Starting Bean: polling://test-sumologic/1343134043

INFO  2018-07-16 16:14:24,811 [main] org.mule.transport.polling.MessageProcessorPollingMessageReceiver: Connecting clusterizable message receiver
2018-07-16 16:14:24,811 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,811 +1000 [main] INFO  org.mule.transport.polling.MessageProcessorPollingMessageReceiver - Connecting clusterizable message receiver

INFO  2018-07-16 16:14:24,812 [main] org.mule.lifecycle.AbstractLifecycleManager: Starting: 'null'. Object is: MessageProcessorPollingMessageReceiver
2018-07-16 16:14:24,812 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,812 +1000 [main] INFO  org.mule.lifecycle.AbstractLifecycleManager - Starting: 'null'. Object is: MessageProcessorPollingMessageReceiver

INFO  2018-07-16 16:14:24,812 [main] org.mule.transport.polling.MessageProcessorPollingMessageReceiver: Starting clusterizable message receiver
2018-07-16 16:14:24,813 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,812 +1000 [main] INFO  org.mule.transport.polling.MessageProcessorPollingMessageReceiver - Starting clusterizable message receiver

INFO  2018-07-16 16:14:24,819 [main] org.mule.module.management.agent.WrapperManagerAgent: This JVM hasn't been launched by the wrapper, the agent will not run.
2018-07-16 16:14:24,819 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,819 +1000 [main] INFO  org.mule.module.management.agent.WrapperManagerAgent - This JVM hasn't been launched by the wrapper, the agent will not run.

INFO  2018-07-16 16:14:24,866 [main] org.mule.module.management.agent.AbstractJmxAgent: Attempting to register service with name: Mule.7be4e690-88bf-11e8-9fb2-0242abacb94c:type=Endpoint,service="test-sumologic",connector=connector.polling.mule.default,name="endpoint.polling.1912630717"
2018-07-16 16:14:24,866 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,866 +1000 [main] INFO  org.mule.module.management.agent.AbstractJmxAgent - Attempting to register service with name: Mule.7be4e690-88bf-11e8-9fb2-0242abacb94c:type=Endpoint,service="test-sumologic",connector=connector.polling.mule.default,name="endpoint.polling.1912630717"

INFO  2018-07-16 16:14:24,868 [main] org.mule.module.management.agent.AbstractJmxAgent: Registered Endpoint Service with name: Mule.7be4e690-88bf-11e8-9fb2-0242abacb94c:type=Endpoint,service="test-sumologic",connector=connector.polling.mule.default,name="endpoint.polling.1912630717"
2018-07-16 16:14:24,868 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,868 +1000 [main] INFO  org.mule.module.management.agent.AbstractJmxAgent - Registered Endpoint Service with name: Mule.7be4e690-88bf-11e8-9fb2-0242abacb94c:type=Endpoint,service="test-sumologic",connector=connector.polling.mule.default,name="endpoint.polling.1912630717"

INFO  2018-07-16 16:14:24,871 [main] org.mule.module.management.agent.AbstractJmxAgent: Registered Connector Service with name Mule.7be4e690-88bf-11e8-9fb2-0242abacb94c:type=Connector,name="connector.polling.mule.default"
2018-07-16 16:14:24,871 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,871 +1000 [main] INFO  org.mule.module.management.agent.AbstractJmxAgent - Registered Connector Service with name Mule.7be4e690-88bf-11e8-9fb2-0242abacb94c:type=Connector,name="connector.polling.mule.default"

INFO  2018-07-16 16:14:24,878 [main] org.mule.DefaultMuleContext: 
**********************************************************************
* Mule Runtime and Integration Platform                              *
* Version: 3.9.0 Build: d8737b4a                                     *
* MuleSoft, Inc.                                                     *
* For more information go to                                         *
* http://www.mulesoft.com/mule-esb-enterprise                        *
*                                                                    *
* Server started: 7/16/18 4:14 PM                                    *
* Server ID: 7be4e690-88bf-11e8-9fb2-0242abacb94c                    *
* JDK: 1.8.0_151 (mixed mode)                                        *
* OS encoding: UTF-8, Mule encoding: UTF-8                           *
* OS: Linux (4.4.0-127-generic, amd64)                               *
* Host: vm-rebecca (127.0.1.1)                                       *
*                                                                    *
* Agents Running:                                                    *
*   Batch module default engine                                      *
*   JMX Agent                                                        *
*   DevKit Extension Information                                     *
*   Wrapper Manager                                                  *
**********************************************************************
2018-07-16 16:14:24,878 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,878 +1000 [main] INFO  org.mule.DefaultMuleContext - 
**********************************************************************
* Mule Runtime and Integration Platform                              *
* Version: 3.9.0 Build: d8737b4a                                     *
* MuleSoft, Inc.                                                     *
* For more information go to                                         *
* http://www.mulesoft.com/mule-esb-enterprise                        *
*                                                                    *
* Server started: 7/16/18 4:14 PM                                    *
* Server ID: 7be4e690-88bf-11e8-9fb2-0242abacb94c                    *
* JDK: 1.8.0_151 (mixed mode)                                        *
* OS encoding: UTF-8, Mule encoding: UTF-8                           *
* OS: Linux (4.4.0-127-generic, amd64)                               *
* Host: vm-rebecca (127.0.1.1)                                       *
*                                                                    *
* Agents Running:                                                    *
*   Batch module default engine                                      *
*   JMX Agent                                                        *
*   DevKit Extension Information                                     *
*   Wrapper Manager                                                  *
**********************************************************************

INFO  2018-07-16 16:14:24,878 [main] org.mule.module.launcher.coreextension.DefaultMuleCoreExtensionManager: Starting core extensions
2018-07-16 16:14:24,879 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,878 +1000 [main] INFO  org.mule.module.launcher.coreextension.DefaultMuleCoreExtensionManager - Starting core extensions

INFO  2018-07-16 16:14:24,977 [main] org.mule.construct.FlowConstructLifecycleManager: Stopping flow: test-sumologic
2018-07-16 16:14:24,978 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,977 +1000 [main] INFO  org.mule.construct.FlowConstructLifecycleManager - Stopping flow: test-sumologic

INFO  2018-07-16 16:14:24,977 [main] org.mule.transport.polling.MessageProcessorPollingConnector: Removing listener on endpointUri: polling://-1912630717
2018-07-16 16:14:24,978 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:24,977 +1000 [main] INFO  org.mule.transport.polling.MessageProcessorPollingConnector - Removing listener on endpointUri: polling://-1912630717

INFO  2018-07-16 16:14:25,001 [main] org.mule.lifecycle.AbstractLifecycleManager: Stopping: 'null'. Object is: MessageProcessorPollingMessageReceiver
2018-07-16 16:14:25,001 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:25,001 +1000 [main] INFO  org.mule.lifecycle.AbstractLifecycleManager - Stopping: 'null'. Object is: MessageProcessorPollingMessageReceiver

INFO  2018-07-16 16:14:25,002 [main] org.mule.lifecycle.AbstractLifecycleManager: Stopping Bean: polling://test-sumologic/1343134043
2018-07-16 16:14:25,002 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:25,002 +1000 [main] INFO  org.mule.lifecycle.AbstractLifecycleManager - Stopping Bean: polling://test-sumologic/1343134043

INFO  2018-07-16 16:14:25,004 [main] org.mule.lifecycle.AbstractLifecycleManager: Disposing: 'null'. Object is: MessageProcessorPollingMessageReceiver
2018-07-16 16:14:25,004 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:25,004 +1000 [main] INFO  org.mule.lifecycle.AbstractLifecycleManager - Disposing: 'null'. Object is: MessageProcessorPollingMessageReceiver

INFO  2018-07-16 16:14:25,015 [main] org.mule.lifecycle.AbstractLifecycleManager: Disposing Bean: polling://test-sumologic/1343134043
2018-07-16 16:14:25,020 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:25,015 +1000 [main] INFO  org.mule.lifecycle.AbstractLifecycleManager - Disposing Bean: polling://test-sumologic/1343134043

INFO  2018-07-16 16:14:25,016 [main] org.mule.processor.SedaStageLifecycleManager: Stopping service: test-sumologic.stage1
2018-07-16 16:14:25,020 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:25,016 +1000 [main] INFO  org.mule.processor.SedaStageLifecycleManager - Stopping service: test-sumologic.stage1

INFO  2018-07-16 16:14:25,087 [main] org.mule.lifecycle.AbstractLifecycleManager: Stopping model: _muleSystemModel
2018-07-16 16:14:25,088 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:25,087 +1000 [main] INFO  org.mule.lifecycle.AbstractLifecycleManager - Stopping model: _muleSystemModel

INFO  2018-07-16 16:14:25,091 [main] org.mule.lifecycle.AbstractLifecycleManager: Stopping connector: connector.polling.mule.default
2018-07-16 16:14:25,091 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:25,091 +1000 [main] INFO  org.mule.lifecycle.AbstractLifecycleManager - Stopping connector: connector.polling.mule.default

INFO  2018-07-16 16:14:25,095 [main] org.mule.util.queue.QueueXaResourceManager: Stopping ResourceManager
2018-07-16 16:14:25,095 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:25,095 +1000 [main] INFO  org.mule.util.queue.QueueXaResourceManager - Stopping ResourceManager

INFO  2018-07-16 16:14:25,095 [main] org.mule.util.queue.QueueXaResourceManager: Stopped ResourceManager
2018-07-16 16:14:25,105 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:25,095 +1000 [main] INFO  org.mule.util.queue.QueueXaResourceManager - Stopped ResourceManager

INFO  2018-07-16 16:14:25,128 [main] org.mule.lifecycle.AbstractLifecycleManager: Disposing RegistryBroker
2018-07-16 16:14:25,137 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:25,128 +1000 [main] INFO  org.mule.lifecycle.AbstractLifecycleManager - Disposing RegistryBroker

INFO  2018-07-16 16:14:25,130 [main] org.mule.construct.FlowConstructLifecycleManager: Disposing flow: test-sumologic
2018-07-16 16:14:25,138 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:25,130 +1000 [main] INFO  org.mule.construct.FlowConstructLifecycleManager - Disposing flow: test-sumologic

INFO  2018-07-16 16:14:25,130 [main] org.mule.processor.SedaStageLifecycleManager: Disposing service: test-sumologic.stage1
2018-07-16 16:14:25,138 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:25,130 +1000 [main] INFO  org.mule.processor.SedaStageLifecycleManager - Disposing service: test-sumologic.stage1

INFO  2018-07-16 16:14:25,140 [main] org.mule.lifecycle.AbstractLifecycleManager: Disposing model: _muleSystemModel
2018-07-16 16:14:25,140 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:25,140 +1000 [main] INFO  org.mule.lifecycle.AbstractLifecycleManager - Disposing model: _muleSystemModel

INFO  2018-07-16 16:14:25,146 [main] org.mule.transport.polling.MessageProcessorPollingConnector: Disconnected: MessageProcessorPollingConnector
{
  name=connector.polling.mule.default
  lifecycle=stop
  this=17c7cc93
  numberOfConcurrentTransactedReceivers=4
  createMultipleTransactedReceivers=true
  connected=true
  supportedProtocols=[polling]
  serviceOverrides=<none>
}

2018-07-16 16:14:25,147 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:25,146 +1000 [main] INFO  org.mule.transport.polling.MessageProcessorPollingConnector - Disconnected: MessageProcessorPollingConnector
{
  name=connector.polling.mule.default
  lifecycle=stop
  this=17c7cc93
  numberOfConcurrentTransactedReceivers=4
  createMultipleTransactedReceivers=true
  connected=true
  supportedProtocols=[polling]
  serviceOverrides=<none>
}

INFO  2018-07-16 16:14:25,151 [main] org.mule.lifecycle.AbstractLifecycleManager: Disposing connector: connector.polling.mule.default
2018-07-16 16:14:25,152 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:25,151 +1000 [main] INFO  org.mule.lifecycle.AbstractLifecycleManager - Disposing connector: connector.polling.mule.default

INFO  2018-07-16 16:14:25,162 [main] org.mule.munit.runner.spring.config.MunitApplicationContext: Closing org.mule.munit.runner.spring.config.MunitApplicationContext@30fffb53: startup date [Mon Jul 16 16:14:23 AEST 2018]; root of context hierarchy
2018-07-16 16:14:25,163 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:25,162 +1000 [main] INFO  org.mule.munit.runner.spring.config.MunitApplicationContext - Closing org.mule.munit.runner.spring.config.MunitApplicationContext@30fffb53: startup date [Mon Jul 16 16:14:23 AEST 2018]; root of context hierarchy

INFO  2018-07-16 16:14:25,174 [main] org.mule.DefaultMuleContext: 
**********************************************************************
* Mule Context shut down normally on: 7/16/18 4:14 PM                *
* Server was up for: 0 days, 0 hours, 0 mins, 0.620 sec              *
**********************************************************************
2018-07-16 16:14:25,174 Log4j2-TF-1-AsyncLoggerConfig-3 DEBUG Sending messge to Sumo: 2018-07-16 16:14:25,174 +1000 [main] INFO  org.mule.DefaultMuleContext - 
**********************************************************************
* Mule Context shut down normally on: 7/16/18 4:14 PM                *
* Server was up for: 0 days, 0 hours, 0 mins, 0.620 sec              *
**********************************************************************

[org.mule.munit.remote.RemoteRunner]Done
2018-07-16 16:14:25,290 pool-1-thread-1 DEBUG Stopping LoggerContext[name=5700d6b1, org.apache.logging.log4j.core.LoggerContext@4b476233]
2018-07-16 16:14:25,291 pool-1-thread-1 DEBUG Stopping LoggerContext[name=5700d6b1, org.apache.logging.log4j.core.LoggerContext@4b476233]...
2018-07-16 16:14:25,302 pool-1-thread-1 DEBUG Stopping SumoLogicAppender SumoAppender
2018-07-16 16:14:25,316 pool-1-thread-1 DEBUG flusher has been stopped
2018-07-16 16:14:25,316 pool-1-thread-1 DEBUG SumoLogicAppender SumoAppender has been stopped
2018-07-16 16:14:25,320 pool-1-thread-1 DEBUG Shutting down OutputStreamManager SYSTEM_OUT.false.false
2018-07-16 16:14:25,323 pool-1-thread-1 DEBUG Shut down OutputStreamManager SYSTEM_OUT.false.false, all resources released: true
2018-07-16 16:14:25,323 pool-1-thread-1 DEBUG Appender Console stopped with status true
2018-07-16 16:14:25,323 pool-1-thread-1 DEBUG Stopped XmlConfiguration[location=/home/vagrant/AnypointStudio/workspace-6-4/test-logging/target/test-classes/log4j2-test.xml] OK
2018-07-16 16:14:25,323 pool-1-thread-1 DEBUG Stopped LoggerContext[name=5700d6b1, org.apache.logging.log4j.core.LoggerContext@4b476233] with status true
rvmiller89 commented 6 years ago

@peterc100 I think the JVM is being forcibly killed before flush completes. With flushAllBeforeStopping="true", we expect to see the following logs that indicate the HTTP POST to Sumo completed:

2018-07-13 10:43:17,284 pool-1-thread-1 DEBUG Sending out data
2018-07-13 10:43:17,636 pool-1-thread-1 DEBUG Successfully sent log request to Sumo Logic
2018-07-13 10:43:17,636 pool-1-thread-1 DEBUG flusher has been stopped
2018-07-13 10:43:17,638 pool-1-thread-1 DEBUG SumoLogicAppender SumoAppender has been stopped

but we don't receive any logs after Sending out data. You may need to modify the application shutdown code, or add the sleep condition you mentioned before. Can I go ahead and close this issue?

peterc100 commented 6 years ago

yeah, i'm not sure adding such delays to each and every Mule flow and app that may result in the app closing is something we'd want to do if we could avoid it. it's one thing to do it in a single test flow, but another thing as a general solution.

i'm actually going to pursue this with Sumologic directly. we have some local contacts here that we can use.

peterc100 commented 6 years ago

as for this issue, that's up to you, but we don't seem to have a viable Mule - log4j2-appender - Sumologic solution, at the moment.

rvmiller89 commented 6 years ago

@peterc100 one thing you can try is invoking LogManager.shutdown(); explicitly from your application, or in a afterAll() function that runs as part of your test suite. The goal here is to allow the log4j shutdown hook to fully execute since it seems to be terminated before the shutdown hook is completed.

peterc100 commented 6 years ago

well this is the weird thing, simply introducing flushAllBeforeStopping="true" leads to the following debug messages and the flow freezing (not ending) before the first step of the flow is executed

2018-07-19 11:16:41,913 main DEBUG Stopping SumoLogicAppender SumoAppender
2018-07-19 11:16:41,921 main DEBUG Thu Jul 19 11:16:41 AEST 2018 - Flushing and sending out 3 messages (0 messages left)
2018-07-19 11:16:41,925 main DEBUG Sending out data

so, we are not in a position to introduce a LogManager.shutdown() after the test since it never gets that far (we don't execute any steps in the test before it freezes)

rvmiller89 commented 6 years ago

That's really strange. The log4j appender may not be the best solution for the short-lived JVM nature of a test framework. A better solution may be to persist logs to disk and use an installed collector to collect and send to Sumo.

peterc100 commented 6 years ago

yeah, i've been trying to remove mulesoft from the equation here and just play around with log4j2 using groovy and set up a sumologic / log4j2-appender test in that, but haven't made much progress yet.

thanks for your help, but i don't think there's much more to be done from the log4j2-appender side, we have some local sumologic support here and i think we'll have to engage them for some general guidance.

i think a locally installed agent may be the only other obvious solution, which'd require installing mule apps on our own server which we've avoided so far by using Mulesoft's cloudhub platform; we'll see how we go.

thanks again.

rvmiller89 commented 6 years ago

No problem. Will close the issue here.