[
https://issues.apache.org/jira/browse/LOG4J2-2687?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16922718#comment-16922718
]
Curtis Patrick commented on LOG4J2-2687:
----------------------------------------
[~mattsicker]
First, thanks for being responsive.
Second, I out on vacation through next week, so I have to finish a few things
before I leave, so I need to put this to bed.
Update this morning...load time is now 11s. *shrug*
wrt narrowing it down, I did try stepping down as deep as I could with VSCode
(I do not yet know how to tell VSCode to reference the Log4j2 source code.)
I got as far as `LogManager::getContext` @ line 194:
{code:java}
public static LoggerContext getContext(final ClassLoader loader, final
boolean currentContext) {
try {
return factory.getContext(FQCN, loader, null, currentContext);
<=== This line
} catch (final IllegalStateException ex) {
LOGGER.warn(ex.getMessage() + " Using SimpleLogger");
return new SimpleLoggerContextFactory().getContext(FQCN, loader,
null, currentContext);
}
}{code}
At this point, I'm just looking at the call stack.
I went a different route, of just pausing the debugger during the pause and I
this was often the line.
My guess is that the root cause (of the original problem yesterday) appears to
be in the call(s?) :
(Portion of call stack)
{code:java}
Inet6AddressImpl.lookupAllHostAddr(String)[native method]
Inet6AddressImpljava[-1:1]
InetAddress$2.lookupAllHostAddr(String)
InetAddress.java[928:1]
InetAAddress.getAddressesFromNameServices(String, InetAddress)
InetAddress.java [1323:1]
netAddress.getLocalHost()
InetAddress.java [1500:1]
{code}
I thought this stack overflow question had promise:
[https://github.com/netty/netty/issues/6454]
But none of those solutions helped me.
I came across this post specifically about JSM taking a long time to resolve
ip-address:
[https://stackoverflow.com/questions/39636792/jvm-takes-a-long-time-to-resolve-ip-address-for-localhost/39698914#39698914]
Again, made the change, flushed DSN, and rebooted, but no luck.
h3. New Log
I spent way too much time today trying to figure out why the times weren't
appearing.
I think it has to do with the `-Dlog4j2.debug` flag enable the StatusLogger.
For the life of me, I couldn't figure out how to set the STATUS_DATA_FORMAT
property to add the time stamp to the StatusLogger output.
I went a slightly different route of using `ts` and `nl` to add line number and
timestamp.
The interesting stuff is
{code:java}
35 2019-09-04 12:22:39 DEBUG StatusLogger
org.apache.logging.log4j.core.util.SystemClock does not support precise
timestamps.
36 2019-09-04 12:22:44 DEBUG StatusLogger Not in a ServletContext
environment, thus not loading WebLookup plugin.
{code}
and
{code:java}
145 2019-09-04 12:22:44 DEBUG StatusLogger Closing BufferedInputStream
java.io.BufferedInputStream@782663d3
146 2019-09-04 12:22:49 DEBUG StatusLogger Apache Log4j Core 2.12.1
initializing configuration
XmlConfiguration[location=/Users/cpatrick/working/incubation/unidata-independence/phoenix/log4j2-vscode-very-slow/target/classes/log4j2.xml]
{code}
Full log
{code:java}
$ mvn -Dlog4j2.debug test 2>&1 | ts '%F %T' | nl
1 2019-09-04 12:40:44 [INFO] Scanning for projects...
2 2019-09-04 12:40:44 [INFO]
3 2019-09-04 12:40:44 [INFO] -----------------------<
patrick.curtis:log4j2 >------------------------
4 2019-09-04 12:40:44 [INFO] Building log4j2 1.0-SNAPSHOT
5 2019-09-04 12:40:44 [INFO] --------------------------------[ jar
]---------------------------------
6 2019-09-04 12:40:44 [INFO]
7 2019-09-04 12:40:44 [INFO] --- maven-resources-plugin:2.6:resources
(default-resources) @ log4j2 ---
8 2019-09-04 12:40:44 [INFO] Using 'UTF-8' encoding to copy filtered
resources.
9 2019-09-04 12:40:44 [INFO] Copying 1 resource
10 2019-09-04 12:40:44 [INFO]
11 2019-09-04 12:40:44 [INFO] --- maven-compiler-plugin:3.1:compile
(default-compile) @ log4j2 ---
12 2019-09-04 12:40:44 [INFO] Nothing to compile - all classes are up to
date
13 2019-09-04 12:40:44 [INFO]
14 2019-09-04 12:40:44 [INFO] --- maven-resources-plugin:2.6:testResources
(default-testResources) @ log4j2 ---
15 2019-09-04 12:40:44 [INFO] Using 'UTF-8' encoding to copy filtered
resources.
16 2019-09-04 12:40:44 [INFO] skip non existing resourceDirectory
/Users/cpatrick/working/incubation/unidata-independence/phoenix/log4j2-vscode-very-slow/src/test/resources
17 2019-09-04 12:40:44 [INFO]
18 2019-09-04 12:40:44 [INFO] --- maven-compiler-plugin:3.1:testCompile
(default-testCompile) @ log4j2 ---
19 2019-09-04 12:40:44 [INFO] Nothing to compile - all classes are up to
date
20 2019-09-04 12:40:44 [INFO]
21 2019-09-04 12:40:44 [INFO] --- maven-surefire-plugin:2.12.4:test
(default-test) @ log4j2 ---
22 2019-09-04 12:40:44 [INFO] Surefire report directory:
/Users/cpatrick/working/incubation/unidata-independence/phoenix/log4j2-vscode-very-slow/target/surefire-reports
23 2019-09-04 12:40:45
24 2019-09-04 12:40:45
-------------------------------------------------------
25 2019-09-04 12:40:45 T E S T S
26 2019-09-04 12:40:45
-------------------------------------------------------
27 2019-09-04 12:40:45 Running patrick.curtis.AppTest
28 2019-09-04 12:40:45 >>>> 1. Creating App instance...
29 2019-09-04 12:40:45 .... 1. App instantiation duration (ms): 1
30 2019-09-04 12:40:45 >>>> 2. Initializing logger
31 2019-09-04 12:40:45 DEBUG StatusLogger Using ShutdownCallbackRegistry
class org.apache.logging.log4j.core.util.DefaultShutdownCallbackRegistry
32 2019-09-04 12:40:45 DEBUG StatusLogger Not in a ServletContext
environment, thus not loading WebLookup plugin.
33 2019-09-04 12:40:45 DEBUG StatusLogger
AsyncLogger.ThreadNameStrategy=UNCACHED (user specified null, default is
UNCACHED)
34 2019-09-04 12:40:45 TRACE StatusLogger Using default SystemClock for
timestamps.
35 2019-09-04 12:40:45 DEBUG StatusLogger
org.apache.logging.log4j.core.util.SystemClock does not support precise
timestamps.
36 2019-09-04 12:40:50 DEBUG StatusLogger Not in a ServletContext
environment, thus not loading WebLookup plugin.
37 2019-09-04 12:40:50 DEBUG StatusLogger Took 0.073388 seconds to load
209 plugins from sun.misc.Launcher$AppClassLoader@4aa298b7
38 2019-09-04 12:40:50 DEBUG StatusLogger PluginManager 'Converter' found
44 plugins
39 2019-09-04 12:40:50 DEBUG StatusLogger Starting OutputStreamManager
SYSTEM_OUT.false.false-1
40 2019-09-04 12:40:50 DEBUG StatusLogger Starting
LoggerContext[name=4aa298b7,
org.apache.logging.log4j.core.LoggerContext@23fe1d71]...
41 2019-09-04 12:40:50 DEBUG StatusLogger Reconfiguration started for
context[name=4aa298b7] at URI null
(org.apache.logging.log4j.core.LoggerContext@23fe1d71) with optional
ClassLoader: null
42 2019-09-04 12:40:50 DEBUG StatusLogger Not in a ServletContext
environment, thus not loading WebLookup plugin.
43 2019-09-04 12:40:50 DEBUG StatusLogger PluginManager
'ConfigurationFactory' found 4 plugins
44 2019-09-04 12:40:50 DEBUG StatusLogger Not in a ServletContext
environment, thus not loading WebLookup plugin.
45 2019-09-04 12:40:50 DEBUG StatusLogger Not in a ServletContext
environment, thus not loading WebLookup plugin.
46 2019-09-04 12:40:50 DEBUG StatusLogger Missing dependencies for Yaml
support, ConfigurationFactory
org.apache.logging.log4j.core.config.yaml.YamlConfigurationFactory is inactive
47 2019-09-04 12:40:50 DEBUG StatusLogger Not in a ServletContext
environment, thus not loading WebLookup plugin.
48 2019-09-04 12:40:50 DEBUG StatusLogger Missing dependencies for Json
support, ConfigurationFactory
org.apache.logging.log4j.core.config.json.JsonConfigurationFactory is inactive
49 2019-09-04 12:40:50 DEBUG StatusLogger Not in a ServletContext
environment, thus not loading WebLookup plugin.
50 2019-09-04 12:40:50 DEBUG StatusLogger Using configurationFactory
org.apache.logging.log4j.core.config.ConfigurationFactory$Factory@3891771e
51 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test4aa298b7.properties] using context class loader
sun.misc.Launcher$AppClassLoader@4aa298b7.
52 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test4aa298b7.properties] using
sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
53 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test4aa298b7.properties] using
sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
54 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test4aa298b7.properties] using ClassLoader.getSystemResource().
55 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test4aa298b7.yml] using context class loader
sun.misc.Launcher$AppClassLoader@4aa298b7.
56 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test4aa298b7.yml] using sun.misc.Launcher$AppClassLoader@4aa298b7 class
loader.
57 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test4aa298b7.yml] using sun.misc.Launcher$AppClassLoader@4aa298b7 class
loader.
58 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test4aa298b7.yml] using ClassLoader.getSystemResource().
59 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test4aa298b7.yaml] using context class loader
sun.misc.Launcher$AppClassLoader@4aa298b7.
60 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test4aa298b7.yaml] using sun.misc.Launcher$AppClassLoader@4aa298b7
class loader.
61 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test4aa298b7.yaml] using sun.misc.Launcher$AppClassLoader@4aa298b7
class loader.
62 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test4aa298b7.yaml] using ClassLoader.getSystemResource().
63 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test4aa298b7.json] using context class loader
sun.misc.Launcher$AppClassLoader@4aa298b7.
64 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test4aa298b7.json] using sun.misc.Launcher$AppClassLoader@4aa298b7
class loader.
65 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test4aa298b7.json] using sun.misc.Launcher$AppClassLoader@4aa298b7
class loader.
66 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test4aa298b7.json] using ClassLoader.getSystemResource().
67 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test4aa298b7.jsn] using context class loader
sun.misc.Launcher$AppClassLoader@4aa298b7.
68 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test4aa298b7.jsn] using sun.misc.Launcher$AppClassLoader@4aa298b7 class
loader.
69 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test4aa298b7.jsn] using sun.misc.Launcher$AppClassLoader@4aa298b7 class
loader.
70 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test4aa298b7.jsn] using ClassLoader.getSystemResource().
71 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test4aa298b7.xml] using context class loader
sun.misc.Launcher$AppClassLoader@4aa298b7.
72 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test4aa298b7.xml] using sun.misc.Launcher$AppClassLoader@4aa298b7 class
loader.
73 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test4aa298b7.xml] using sun.misc.Launcher$AppClassLoader@4aa298b7 class
loader.
74 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test4aa298b7.xml] using ClassLoader.getSystemResource().
75 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test.properties] using context class loader
sun.misc.Launcher$AppClassLoader@4aa298b7.
76 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test.properties] using sun.misc.Launcher$AppClassLoader@4aa298b7 class
loader.
77 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test.properties] using sun.misc.Launcher$AppClassLoader@4aa298b7 class
loader.
78 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test.properties] using ClassLoader.getSystemResource().
79 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2-test.yml]
using context class loader sun.misc.Launcher$AppClassLoader@4aa298b7.
80 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2-test.yml]
using sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
81 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2-test.yml]
using sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
82 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2-test.yml]
using ClassLoader.getSystemResource().
83 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test.yaml] using context class loader
sun.misc.Launcher$AppClassLoader@4aa298b7.
84 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test.yaml] using sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
85 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test.yaml] using sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
86 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test.yaml] using ClassLoader.getSystemResource().
87 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test.json] using context class loader
sun.misc.Launcher$AppClassLoader@4aa298b7.
88 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test.json] using sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
89 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test.json] using sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
90 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2-test.json] using ClassLoader.getSystemResource().
91 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2-test.jsn]
using context class loader sun.misc.Launcher$AppClassLoader@4aa298b7.
92 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2-test.jsn]
using sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
93 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2-test.jsn]
using sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
94 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2-test.jsn]
using ClassLoader.getSystemResource().
95 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2-test.xml]
using context class loader sun.misc.Launcher$AppClassLoader@4aa298b7.
96 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2-test.xml]
using sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
97 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2-test.xml]
using sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
98 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2-test.xml]
using ClassLoader.getSystemResource().
99 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j24aa298b7.properties] using context class loader
sun.misc.Launcher$AppClassLoader@4aa298b7.
100 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j24aa298b7.properties] using sun.misc.Launcher$AppClassLoader@4aa298b7
class loader.
101 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j24aa298b7.properties] using sun.misc.Launcher$AppClassLoader@4aa298b7
class loader.
102 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j24aa298b7.properties] using ClassLoader.getSystemResource().
103 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j24aa298b7.yml] using context class loader
sun.misc.Launcher$AppClassLoader@4aa298b7.
104 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j24aa298b7.yml] using sun.misc.Launcher$AppClassLoader@4aa298b7 class
loader.
105 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j24aa298b7.yml] using sun.misc.Launcher$AppClassLoader@4aa298b7 class
loader.
106 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j24aa298b7.yml] using ClassLoader.getSystemResource().
107 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j24aa298b7.yaml] using context class loader
sun.misc.Launcher$AppClassLoader@4aa298b7.
108 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j24aa298b7.yaml] using sun.misc.Launcher$AppClassLoader@4aa298b7 class
loader.
109 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j24aa298b7.yaml] using sun.misc.Launcher$AppClassLoader@4aa298b7 class
loader.
110 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j24aa298b7.yaml] using ClassLoader.getSystemResource().
111 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j24aa298b7.json] using context class loader
sun.misc.Launcher$AppClassLoader@4aa298b7.
112 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j24aa298b7.json] using sun.misc.Launcher$AppClassLoader@4aa298b7 class
loader.
113 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j24aa298b7.json] using sun.misc.Launcher$AppClassLoader@4aa298b7 class
loader.
114 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j24aa298b7.json] using ClassLoader.getSystemResource().
115 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j24aa298b7.jsn] using context class loader
sun.misc.Launcher$AppClassLoader@4aa298b7.
116 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j24aa298b7.jsn] using sun.misc.Launcher$AppClassLoader@4aa298b7 class
loader.
117 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j24aa298b7.jsn] using sun.misc.Launcher$AppClassLoader@4aa298b7 class
loader.
118 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j24aa298b7.jsn] using ClassLoader.getSystemResource().
119 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j24aa298b7.xml] using context class loader
sun.misc.Launcher$AppClassLoader@4aa298b7.
120 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j24aa298b7.xml] using sun.misc.Launcher$AppClassLoader@4aa298b7 class
loader.
121 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j24aa298b7.xml] using sun.misc.Launcher$AppClassLoader@4aa298b7 class
loader.
122 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j24aa298b7.xml] using ClassLoader.getSystemResource().
123 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2.properties] using context class loader
sun.misc.Launcher$AppClassLoader@4aa298b7.
124 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2.properties] using sun.misc.Launcher$AppClassLoader@4aa298b7 class
loader.
125 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2.properties] using sun.misc.Launcher$AppClassLoader@4aa298b7 class
loader.
126 2019-09-04 12:40:50 TRACE StatusLogger Trying to find
[log4j2.properties] using ClassLoader.getSystemResource().
127 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2.yml]
using context class loader sun.misc.Launcher$AppClassLoader@4aa298b7.
128 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2.yml]
using sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
129 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2.yml]
using sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
130 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2.yml]
using ClassLoader.getSystemResource().
131 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2.yaml]
using context class loader sun.misc.Launcher$AppClassLoader@4aa298b7.
132 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2.yaml]
using sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
133 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2.yaml]
using sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
134 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2.yaml]
using ClassLoader.getSystemResource().
135 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2.json]
using context class loader sun.misc.Launcher$AppClassLoader@4aa298b7.
136 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2.json]
using sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
137 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2.json]
using sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
138 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2.json]
using ClassLoader.getSystemResource().
139 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2.jsn]
using context class loader sun.misc.Launcher$AppClassLoader@4aa298b7.
140 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2.jsn]
using sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
141 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2.jsn]
using sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
142 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2.jsn]
using ClassLoader.getSystemResource().
143 2019-09-04 12:40:50 TRACE StatusLogger Trying to find [log4j2.xml]
using context class loader sun.misc.Launcher$AppClassLoader@4aa298b7.
144 2019-09-04 12:40:50 DEBUG StatusLogger Not in a ServletContext
environment, thus not loading WebLookup plugin.
145 2019-09-04 12:40:50 DEBUG StatusLogger Closing BufferedInputStream
java.io.BufferedInputStream@782663d3
146 2019-09-04 12:40:55 DEBUG StatusLogger Apache Log4j Core 2.12.1
initializing configuration
XmlConfiguration[location=/Users/cpatrick/working/incubation/unidata-independence/phoenix/log4j2-vscode-very-slow/target/classes/log4j2.xml]
147 2019-09-04 12:40:55 DEBUG StatusLogger Installed 1 script engine
148 2019-09-04 12:40:56 DEBUG StatusLogger Oracle Nashorn version:
1.8.0_172, language: ECMAScript, threading: Not Thread Safe, compile: true,
names: [nashorn, Nashorn, js, JS, JavaScript, javascript, ECMAScript,
ecmascript], factory class: jdk.nashorn.api.scripting.NashornScriptEngineFactory
149 2019-09-04 12:40:56 DEBUG StatusLogger PluginManager 'Core' found 118
plugins
150 2019-09-04 12:40:56 DEBUG StatusLogger PluginManager 'Level' found 0
plugins
151 2019-09-04 12:40:56 DEBUG StatusLogger Building Plugin[name=property,
class=org.apache.logging.log4j.core.config.Property].
152 2019-09-04 12:40:56 TRACE StatusLogger TypeConverterRegistry
initializing.
153 2019-09-04 12:40:56 DEBUG StatusLogger PluginManager 'TypeConverter'
found 26 plugins
154 2019-09-04 12:40:56 DEBUG StatusLogger
createProperty(name="LOG_PATTERN", value="%d{yyyy-MM-dd HH:mm:ss.SSS} %5p
%X{mdcData} --- %-40.40c{1.} : %m%n%ex")
155 2019-09-04 12:40:56 DEBUG StatusLogger Building Plugin[name=property,
class=org.apache.logging.log4j.core.config.Property].
156 2019-09-04 12:40:56 DEBUG StatusLogger
createProperty(name="STATUS_DATE_FORMAT", value="yyyy-MM-dd HH:mm:ss.SSS")
157 2019-09-04 12:40:56 DEBUG StatusLogger Building Plugin[name=properties,
class=org.apache.logging.log4j.core.config.PropertiesPlugin].
158 2019-09-04 12:40:56 DEBUG StatusLogger
configureSubstitutor(={LOG_PATTERN=%d{yyyy-MM-dd HH:mm:ss.SSS} %5p %X{mdcData}
--- %-40.40c{1.} : %m%n%ex, STATUS_DATE_FORMAT=yyyy-MM-dd HH:mm:ss.SSS},
Configuration(/Users/cpatrick/working/incubation/unidata-independence/phoenix/log4j2-vscode-very-slow/target/classes/log4j2.xml))
159 2019-09-04 12:40:56 DEBUG StatusLogger PluginManager 'Lookup' found 13
plugins
160 2019-09-04 12:40:56 DEBUG StatusLogger Building Plugin[name=layout,
class=org.apache.logging.log4j.core.layout.PatternLayout].
161 2019-09-04 12:40:56 DEBUG StatusLogger
PatternLayout$Builder(pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} -
%msg%n", PatternSelector=null,
Configuration(/Users/cpatrick/working/incubation/unidata-independence/phoenix/log4j2-vscode-very-slow/target/classes/log4j2.xml),
Replace=null, charset="null", alwaysWriteExceptions="null",
disableAnsi="null", noConsoleNoAnsi="null", header="null", footer="null")
162 2019-09-04 12:40:56 DEBUG StatusLogger PluginManager 'Converter' found
44 plugins
163 2019-09-04 12:40:56 DEBUG StatusLogger Building Plugin[name=appender,
class=org.apache.logging.log4j.core.appender.ConsoleAppender].
164 2019-09-04 12:40:56 DEBUG StatusLogger
ConsoleAppender$Builder(target="SYSTEM_OUT", follow="null", direct="null",
bufferedIo="null", bufferSize="null", immediateFlush="null",
ignoreExceptions="null", PatternLayout(%d{HH:mm:ss.SSS} [%t] %-5level
%logger{36} - %msg%n), name="LogToConsole",
Configuration(/Users/cpatrick/working/incubation/unidata-independence/phoenix/log4j2-vscode-very-slow/target/classes/log4j2.xml),
Filter=null, ={})
165 2019-09-04 12:40:56 DEBUG StatusLogger Starting OutputStreamManager
SYSTEM_OUT.false.false
166 2019-09-04 12:40:56 DEBUG StatusLogger Building Plugin[name=appenders,
class=org.apache.logging.log4j.core.config.AppendersPlugin].
167 2019-09-04 12:40:56 DEBUG StatusLogger createAppenders(={LogToConsole})
168 2019-09-04 12:40:56 DEBUG StatusLogger Building
Plugin[name=AppenderRef,
class=org.apache.logging.log4j.core.config.AppenderRef].
169 2019-09-04 12:40:56 DEBUG StatusLogger
createAppenderRef(ref="LogToConsole", level="null", Filter=null)
170 2019-09-04 12:40:56 DEBUG StatusLogger Building Plugin[name=root,
class=org.apache.logging.log4j.core.config.LoggerConfig$RootLogger].
171 2019-09-04 12:40:56 DEBUG StatusLogger createLogger(additivity="null",
level="TRACE", includeLocation="null", ={LogToConsole}, ={},
Configuration(/Users/cpatrick/working/incubation/unidata-independence/phoenix/log4j2-vscode-very-slow/target/classes/log4j2.xml),
Filter=null)
172 2019-09-04 12:40:56 DEBUG StatusLogger Building Plugin[name=loggers,
class=org.apache.logging.log4j.core.config.LoggersPlugin].
173 2019-09-04 12:40:56 DEBUG StatusLogger createLoggers(={root})
174 2019-09-04 12:40:56 DEBUG StatusLogger Configuration
XmlConfiguration[location=/Users/cpatrick/working/incubation/unidata-independence/phoenix/log4j2-vscode-very-slow/target/classes/log4j2.xml]
initialized
175 2019-09-04 12:40:56 DEBUG StatusLogger Starting configuration
XmlConfiguration[location=/Users/cpatrick/working/incubation/unidata-independence/phoenix/log4j2-vscode-very-slow/target/classes/log4j2.xml]
176 2019-09-04 12:40:56 DEBUG StatusLogger Started configuration
XmlConfiguration[location=/Users/cpatrick/working/incubation/unidata-independence/phoenix/log4j2-vscode-very-slow/target/classes/log4j2.xml]
OK.
177 2019-09-04 12:40:56 TRACE StatusLogger Stopping
org.apache.logging.log4j.core.config.DefaultConfiguration@3567135c...
178 2019-09-04 12:40:56 TRACE StatusLogger DefaultConfiguration notified 1
ReliabilityStrategies that config will be stopped.
179 2019-09-04 12:40:56 TRACE StatusLogger DefaultConfiguration stopping
root LoggerConfig.
180 2019-09-04 12:40:56 TRACE StatusLogger DefaultConfiguration notifying
ReliabilityStrategies that appenders will be stopped.
181 2019-09-04 12:40:56 TRACE StatusLogger DefaultConfiguration stopping
remaining Appenders.
182 2019-09-04 12:40:56 DEBUG StatusLogger Shutting down
OutputStreamManager SYSTEM_OUT.false.false-1
183 2019-09-04 12:40:56 DEBUG StatusLogger Shut down OutputStreamManager
SYSTEM_OUT.false.false-1, all resources released: true
184 2019-09-04 12:40:56 DEBUG StatusLogger Appender DefaultConsole-1
stopped with status true
185 2019-09-04 12:40:56 TRACE StatusLogger DefaultConfiguration stopped 1
remaining Appenders.
186 2019-09-04 12:40:56 TRACE StatusLogger DefaultConfiguration cleaning
Appenders from 1 LoggerConfigs.
187 2019-09-04 12:40:56 DEBUG StatusLogger Stopped
org.apache.logging.log4j.core.config.DefaultConfiguration@3567135c OK
188 2019-09-04 12:40:56 TRACE StatusLogger Reregistering MBeans after
reconfigure.
Selector=org.apache.logging.log4j.core.selector.ClassLoaderContextSelector@609db43b
189 2019-09-04 12:40:56 TRACE StatusLogger Reregistering context (1/1):
'4aa298b7' org.apache.logging.log4j.core.LoggerContext@23fe1d71
190 2019-09-04 12:40:56 TRACE StatusLogger Unregistering but no MBeans
found matching 'org.apache.logging.log4j2:type=4aa298b7'
191 2019-09-04 12:40:56 TRACE StatusLogger Unregistering but no MBeans
found matching 'org.apache.logging.log4j2:type=4aa298b7,component=StatusLogger'
192 2019-09-04 12:40:56 TRACE StatusLogger Unregistering but no MBeans
found matching
'org.apache.logging.log4j2:type=4aa298b7,component=ContextSelector'
193 2019-09-04 12:40:56 TRACE StatusLogger Unregistering but no MBeans
found matching
'org.apache.logging.log4j2:type=4aa298b7,component=Loggers,name=*'
194 2019-09-04 12:40:56 TRACE StatusLogger Unregistering but no MBeans
found matching
'org.apache.logging.log4j2:type=4aa298b7,component=Appenders,name=*'
195 2019-09-04 12:40:56 TRACE StatusLogger Unregistering but no MBeans
found matching
'org.apache.logging.log4j2:type=4aa298b7,component=AsyncAppenders,name=*'
196 2019-09-04 12:40:56 TRACE StatusLogger Unregistering but no MBeans
found matching
'org.apache.logging.log4j2:type=4aa298b7,component=AsyncLoggerRingBuffer'
197 2019-09-04 12:40:56 TRACE StatusLogger Unregistering but no MBeans
found matching
'org.apache.logging.log4j2:type=4aa298b7,component=Loggers,name=*,subtype=RingBuffer'
198 2019-09-04 12:40:56 DEBUG StatusLogger Registering MBean
org.apache.logging.log4j2:type=4aa298b7
199 2019-09-04 12:40:56 DEBUG StatusLogger Registering MBean
org.apache.logging.log4j2:type=4aa298b7,component=StatusLogger
200 2019-09-04 12:40:56 DEBUG StatusLogger Registering MBean
org.apache.logging.log4j2:type=4aa298b7,component=ContextSelector
201 2019-09-04 12:40:56 DEBUG StatusLogger Registering MBean
org.apache.logging.log4j2:type=4aa298b7,component=Loggers,name=
202 2019-09-04 12:40:56 DEBUG StatusLogger Registering MBean
org.apache.logging.log4j2:type=4aa298b7,component=Appenders,name=LogToConsole
203 2019-09-04 12:40:56 TRACE StatusLogger Using default SystemClock for
timestamps.
204 2019-09-04 12:40:56 DEBUG StatusLogger
org.apache.logging.log4j.core.util.SystemClock does not support precise
timestamps.
205 2019-09-04 12:40:56 TRACE StatusLogger Using DummyNanoClock for
nanosecond timestamps.
206 2019-09-04 12:40:56 DEBUG StatusLogger Reconfiguration complete for
context[name=4aa298b7] at URI
/Users/cpatrick/working/incubation/unidata-independence/phoenix/log4j2-vscode-very-slow/target/classes/log4j2.xml
(org.apache.logging.log4j.core.LoggerContext@23fe1d71) with optional
ClassLoader: null
207 2019-09-04 12:40:56 DEBUG StatusLogger Shutdown hook enabled.
Registering a new one.
208 2019-09-04 12:40:56 DEBUG StatusLogger LoggerContext[name=4aa298b7,
org.apache.logging.log4j.core.LoggerContext@23fe1d71] started OK.
209 2019-09-04 12:40:56 .... 2. logger initialization duration (ms): 10816
210 2019-09-04 12:40:56 >>>> 3. Executing writing to logger
211 2019-09-04 12:40:56 12:40:56.168 [main] DEBUG patrick.curtis.App -
@@@@@ debug
212 2019-09-04 12:40:56 12:40:56.171 [main] INFO patrick.curtis.App -
@@@@@ info
213 2019-09-04 12:40:56 12:40:56.172 [main] WARN patrick.curtis.App -
@@@@@ warn
214 2019-09-04 12:40:56 12:40:56.172 [main] ERROR patrick.curtis.App -
@@@@@ error
215 2019-09-04 12:40:56 12:40:56.172 [main] FATAL patrick.curtis.App -
@@@@@ fatal
216 2019-09-04 12:40:56 ..... 3 log writing duration (ms): 7
217 2019-09-04 12:40:56 Tests run: 1, Failures: 0, Errors: 0, Skipped: 0,
Time elapsed: 10.864 sec
218 2019-09-04 12:40:56 DEBUG StatusLogger Stopping
LoggerContext[name=4aa298b7,
org.apache.logging.log4j.core.LoggerContext@23fe1d71]
219 2019-09-04 12:40:56 DEBUG StatusLogger Stopping
LoggerContext[name=4aa298b7,
org.apache.logging.log4j.core.LoggerContext@23fe1d71]...
220 2019-09-04 12:40:56 TRACE StatusLogger Unregistering 1 MBeans:
[org.apache.logging.log4j2:type=4aa298b7]
221 2019-09-04 12:40:56 TRACE StatusLogger Unregistering 1 MBeans:
[org.apache.logging.log4j2:type=4aa298b7,component=StatusLogger]
222 2019-09-04 12:40:56 TRACE StatusLogger Unregistering 1 MBeans:
[org.apache.logging.log4j2:type=4aa298b7,component=ContextSelector]
223 2019-09-04 12:40:56 TRACE StatusLogger Unregistering 1 MBeans:
[org.apache.logging.log4j2:type=4aa298b7,component=Loggers,name=]
224 2019-09-04 12:40:56 TRACE StatusLogger Unregistering 1 MBeans:
[org.apache.logging.log4j2:type=4aa298b7,component=Appenders,name=LogToConsole]
225 2019-09-04 12:40:56 TRACE StatusLogger Unregistering but no MBeans
found matching
'org.apache.logging.log4j2:type=4aa298b7,component=AsyncAppenders,name=*'
226 2019-09-04 12:40:56 TRACE StatusLogger Unregistering but no MBeans
found matching
'org.apache.logging.log4j2:type=4aa298b7,component=AsyncLoggerRingBuffer'
227 2019-09-04 12:40:56 TRACE StatusLogger Unregistering but no MBeans
found matching
'org.apache.logging.log4j2:type=4aa298b7,component=Loggers,name=*,subtype=RingBuffer'
228 2019-09-04 12:40:56 TRACE StatusLogger Stopping
XmlConfiguration[location=/Users/cpatrick/working/incubation/unidata-independence/phoenix/log4j2-vscode-very-slow/target/classes/log4j2.xml]...
229 2019-09-04 12:40:56 TRACE StatusLogger XmlConfiguration notified 2
ReliabilityStrategies that config will be stopped.
230 2019-09-04 12:40:56 TRACE StatusLogger XmlConfiguration stopping 1
LoggerConfigs.
231 2019-09-04 12:40:56 TRACE StatusLogger XmlConfiguration stopping root
LoggerConfig.
232 2019-09-04 12:40:56 TRACE StatusLogger XmlConfiguration notifying
ReliabilityStrategies that appenders will be stopped.
233 2019-09-04 12:40:56 TRACE StatusLogger XmlConfiguration stopping
remaining Appenders.
234 2019-09-04 12:40:56 DEBUG StatusLogger Shutting down
OutputStreamManager SYSTEM_OUT.false.false
235 2019-09-04 12:40:56 DEBUG StatusLogger Shut down OutputStreamManager
SYSTEM_OUT.false.false, all resources released: true
236 2019-09-04 12:40:56 DEBUG StatusLogger Appender LogToConsole stopped
with status true
237 2019-09-04 12:40:56 TRACE StatusLogger XmlConfiguration stopped 1
remaining Appenders.
238 2019-09-04 12:40:56 TRACE StatusLogger XmlConfiguration cleaning
Appenders from 2 LoggerConfigs.
239 2019-09-04 12:40:56 DEBUG StatusLogger Stopped
XmlConfiguration[location=/Users/cpatrick/working/incubation/unidata-independence/phoenix/log4j2-vscode-very-slow/target/classes/log4j2.xml]
OK
240 2019-09-04 12:40:56 DEBUG StatusLogger Stopped
LoggerContext[name=4aa298b7,
org.apache.logging.log4j.core.LoggerContext@23fe1d71] with status true
241 2019-09-04 12:40:56
242 2019-09-04 12:40:56 Results :
243 2019-09-04 12:40:56
244 2019-09-04 12:40:56 Tests run: 1, Failures: 0, Errors: 0, Skipped: 0
245 2019-09-04 12:40:56
246 2019-09-04 12:40:56 [INFO]
------------------------------------------------------------------------
247 2019-09-04 12:40:56 [INFO] BUILD SUCCESS
248 2019-09-04 12:40:56 [INFO]
------------------------------------------------------------------------
249 2019-09-04 12:40:56 [INFO] Total time: 11.920 s
250 2019-09-04 12:40:56 [INFO] Finished at: 2019-09-04T12:40:56-05:00
251 2019-09-04 12:40:56 [INFO]
------------------------------------------------------------------------{code}
> Log4j2 initialize time consuming 5.5s+
> --------------------------------------
>
> Key: LOG4J2-2687
> URL: https://issues.apache.org/jira/browse/LOG4J2-2687
> Project: Log4j 2
> Issue Type: Improvement
> Affects Versions: 2.10.0, 2.11.0, 2.11.1, 2.12.0, 2.12.1
> Environment: Mac OSX 10.14.4 / Java 1.8.0_172-b11
> VSCode 1.37.1
> * Debugger for Java 0.21.0
> * Java Test Runner 0.19.0
> * Java Extension pack 0.8.0
>
> Reporter: Curtis Patrick
> Priority: Minor
> Attachments: SlowLog4j2Startup-2019-09-03.gif
>
>
> I'm just starting to use log4j2 and added it to a new project with a single
> test.
> Testing time went from practically instantaneous to nearly 6 seconds.
> Is this expected?
> The log line immediately before the long delay is:
> {code:java}
> DEBUG StatusLogger Not in a ServletContext environment, thus not loading
> WebLookup plugin.
> {code}
>
> Debugging the tests In VSCode adds another 9 seconds (15 total) to initialize
> the logger.
> I've attached is a gif capture of the test run from a terminal window.
> app.java
> {code:java}
> package patrick.curtis;
> import org.apache.logging.log4j.LogManager;
> import org.apache.logging.log4j.Logger;
> public final class App {
> private static Logger log = null;
> public void initlogger() {
> log = LogManager.getLogger();
> }
> public void foo() {
> log.debug("debug");
> log.info("info");
> log.warn("warn");
> log.error("error");
> log.fatal("fatal");
> }
> }
> {code}
> apptest.java
> {code:java}
> package patrick.curtis;
> import org.junit.Test;
> import java.util.Date;
> /**
> * Unit test for simple App.
> */
> public class AppTest {
> /**
> * Rigorous Test.
> */
> @Test
> public void appTest() {
> long t = new Date().getTime();
> System.out.println(String.format("Initializing app (ms): %d", t));
> App app = new App();
> t = new Date().getTime() - t;
> System.out.println(String.format("...app initialization duration
> (ms): %d", t));
> t = new Date().getTime();
> System.out.println(String.format("Initializing logger (ms): %d", t));
> app.initlogger();
> t = new Date().getTime() - t;
> System.out.println(String.format("...logger initialization duration
> (ms): %d", t));
> t = new Date().getTime();
> System.out.println(String.format("Executing foo() (ms): %d", t));
> app.foo();
> t = new Date().getTime() - t;
> System.out.println(String.format("...foo() execution duration (ms):
> %d", t));
> }
> }
> {code}
>
>
>
> {code:java}
> $ mvn -Dlog4j2.debug test
> -------------------------------------------------------
> T E S T S
> -------------------------------------------------------
> Running patrick.curtis.AppTest
> Initializing app (ms): 1567533450393
> ...app initialization duration (ms): 2
> Initializing logger (ms): 1567533450395
> DEBUG StatusLogger Using ShutdownCallbackRegistry class
> org.apache.logging.log4j.core.util.DefaultShutdownCallbackRegistry
> DEBUG StatusLogger Not in a ServletContext environment, thus not loading
> WebLookup plugin.
> DEBUG StatusLogger AsyncLogger.ThreadNameStrategy=CACHED
> TRACE StatusLogger Using default SystemClock for timestamps.
> DEBUG StatusLogger Not in a ServletContext environment, thus not loading
> WebLookup plugin.
> DEBUG StatusLogger Took 0.059542 seconds to load 202 plugins from
> sun.misc.Launcher$AppClassLoader@4aa298b7
> DEBUG StatusLogger PluginManager 'Converter' found 42 plugins
> DEBUG StatusLogger Starting OutputStreamManager SYSTEM_OUT.false.false-1
> DEBUG StatusLogger Starting LoggerContext[name=4aa298b7,
> org.apache.logging.log4j.core.LoggerContext@480bdb19]...
> DEBUG StatusLogger Reconfiguration started for context[name=4aa298b7] at URI
> null (org.apache.logging.log4j.core.LoggerContext@480bdb19) with optional
> ClassLoader: null
> DEBUG StatusLogger Not in a ServletContext environment, thus not loading
> WebLookup plugin.
> DEBUG StatusLogger PluginManager 'ConfigurationFactory' found 4 plugins
> DEBUG StatusLogger Not in a ServletContext environment, thus not loading
> WebLookup plugin.
> DEBUG StatusLogger Not in a ServletContext environment, thus not loading
> WebLookup plugin.
> DEBUG StatusLogger Missing dependencies for Yaml support,
> ConfigurationFactory
> org.apache.logging.log4j.core.config.yaml.YamlConfigurationFactory is inactive
> DEBUG StatusLogger Not in a ServletContext environment, thus not loading
> WebLookup plugin.
> DEBUG StatusLogger Missing dependencies for Json support,
> ConfigurationFactory
> org.apache.logging.log4j.core.config.json.JsonConfigurationFactory is inactive
> DEBUG StatusLogger Not in a ServletContext environment, thus not loading
> WebLookup plugin.
> DEBUG StatusLogger Using configurationFactory
> org.apache.logging.log4j.core.config.ConfigurationFactory$Factory@51e2adc7
> TRACE StatusLogger Trying to find [log4j2-test4aa298b7.properties] using
> context class loader sun.misc.Launcher$AppClassLoader@4aa298b7.
> TRACE StatusLogger Trying to find [log4j2-test4aa298b7.properties] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2-test4aa298b7.properties] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2-test4aa298b7.properties] using
> ClassLoader.getSystemResource().
> TRACE StatusLogger Trying to find [log4j2-test4aa298b7.yml] using context
> class loader sun.misc.Launcher$AppClassLoader@4aa298b7.
> TRACE StatusLogger Trying to find [log4j2-test4aa298b7.yml] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2-test4aa298b7.yml] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2-test4aa298b7.yml] using
> ClassLoader.getSystemResource().
> TRACE StatusLogger Trying to find [log4j2-test4aa298b7.yaml] using context
> class loader sun.misc.Launcher$AppClassLoader@4aa298b7.
> TRACE StatusLogger Trying to find [log4j2-test4aa298b7.yaml] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2-test4aa298b7.yaml] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2-test4aa298b7.yaml] using
> ClassLoader.getSystemResource().
> TRACE StatusLogger Trying to find [log4j2-test4aa298b7.json] using context
> class loader sun.misc.Launcher$AppClassLoader@4aa298b7.
> TRACE StatusLogger Trying to find [log4j2-test4aa298b7.json] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2-test4aa298b7.json] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2-test4aa298b7.json] using
> ClassLoader.getSystemResource().
> TRACE StatusLogger Trying to find [log4j2-test4aa298b7.jsn] using context
> class loader sun.misc.Launcher$AppClassLoader@4aa298b7.
> TRACE StatusLogger Trying to find [log4j2-test4aa298b7.jsn] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2-test4aa298b7.jsn] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2-test4aa298b7.jsn] using
> ClassLoader.getSystemResource().
> TRACE StatusLogger Trying to find [log4j2-test4aa298b7.xml] using context
> class loader sun.misc.Launcher$AppClassLoader@4aa298b7.
> TRACE StatusLogger Trying to find [log4j2-test4aa298b7.xml] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2-test4aa298b7.xml] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2-test4aa298b7.xml] using
> ClassLoader.getSystemResource().
> TRACE StatusLogger Trying to find [log4j2-test.properties] using context
> class loader sun.misc.Launcher$AppClassLoader@4aa298b7.
> TRACE StatusLogger Trying to find [log4j2-test.properties] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2-test.properties] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2-test.properties] using
> ClassLoader.getSystemResource().
> TRACE StatusLogger Trying to find [log4j2-test.yml] using context class
> loader sun.misc.Launcher$AppClassLoader@4aa298b7.
> TRACE StatusLogger Trying to find [log4j2-test.yml] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2-test.yml] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2-test.yml] using
> ClassLoader.getSystemResource().
> TRACE StatusLogger Trying to find [log4j2-test.yaml] using context class
> loader sun.misc.Launcher$AppClassLoader@4aa298b7.
> TRACE StatusLogger Trying to find [log4j2-test.yaml] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2-test.yaml] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2-test.yaml] using
> ClassLoader.getSystemResource().
> TRACE StatusLogger Trying to find [log4j2-test.json] using context class
> loader sun.misc.Launcher$AppClassLoader@4aa298b7.
> TRACE StatusLogger Trying to find [log4j2-test.json] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2-test.json] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2-test.json] using
> ClassLoader.getSystemResource().
> TRACE StatusLogger Trying to find [log4j2-test.jsn] using context class
> loader sun.misc.Launcher$AppClassLoader@4aa298b7.
> TRACE StatusLogger Trying to find [log4j2-test.jsn] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2-test.jsn] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2-test.jsn] using
> ClassLoader.getSystemResource().
> TRACE StatusLogger Trying to find [log4j2-test.xml] using context class
> loader sun.misc.Launcher$AppClassLoader@4aa298b7.
> TRACE StatusLogger Trying to find [log4j2-test.xml] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2-test.xml] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2-test.xml] using
> ClassLoader.getSystemResource().
> TRACE StatusLogger Trying to find [log4j24aa298b7.properties] using context
> class loader sun.misc.Launcher$AppClassLoader@4aa298b7.
> TRACE StatusLogger Trying to find [log4j24aa298b7.properties] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j24aa298b7.properties] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j24aa298b7.properties] using
> ClassLoader.getSystemResource().
> TRACE StatusLogger Trying to find [log4j24aa298b7.yml] using context class
> loader sun.misc.Launcher$AppClassLoader@4aa298b7.
> TRACE StatusLogger Trying to find [log4j24aa298b7.yml] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j24aa298b7.yml] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j24aa298b7.yml] using
> ClassLoader.getSystemResource().
> TRACE StatusLogger Trying to find [log4j24aa298b7.yaml] using context class
> loader sun.misc.Launcher$AppClassLoader@4aa298b7.
> TRACE StatusLogger Trying to find [log4j24aa298b7.yaml] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j24aa298b7.yaml] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j24aa298b7.yaml] using
> ClassLoader.getSystemResource().
> TRACE StatusLogger Trying to find [log4j24aa298b7.json] using context class
> loader sun.misc.Launcher$AppClassLoader@4aa298b7.
> TRACE StatusLogger Trying to find [log4j24aa298b7.json] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j24aa298b7.json] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j24aa298b7.json] using
> ClassLoader.getSystemResource().
> TRACE StatusLogger Trying to find [log4j24aa298b7.jsn] using context class
> loader sun.misc.Launcher$AppClassLoader@4aa298b7.
> TRACE StatusLogger Trying to find [log4j24aa298b7.jsn] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j24aa298b7.jsn] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j24aa298b7.jsn] using
> ClassLoader.getSystemResource().
> TRACE StatusLogger Trying to find [log4j24aa298b7.xml] using context class
> loader sun.misc.Launcher$AppClassLoader@4aa298b7.
> TRACE StatusLogger Trying to find [log4j24aa298b7.xml] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j24aa298b7.xml] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j24aa298b7.xml] using
> ClassLoader.getSystemResource().
> TRACE StatusLogger Trying to find [log4j2.properties] using context class
> loader sun.misc.Launcher$AppClassLoader@4aa298b7.
> TRACE StatusLogger Trying to find [log4j2.properties] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2.properties] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2.properties] using
> ClassLoader.getSystemResource().
> TRACE StatusLogger Trying to find [log4j2.yml] using context class loader
> sun.misc.Launcher$AppClassLoader@4aa298b7.
> TRACE StatusLogger Trying to find [log4j2.yml] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2.yml] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2.yml] using
> ClassLoader.getSystemResource().
> TRACE StatusLogger Trying to find [log4j2.yaml] using context class loader
> sun.misc.Launcher$AppClassLoader@4aa298b7.
> TRACE StatusLogger Trying to find [log4j2.yaml] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2.yaml] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2.yaml] using
> ClassLoader.getSystemResource().
> TRACE StatusLogger Trying to find [log4j2.json] using context class loader
> sun.misc.Launcher$AppClassLoader@4aa298b7.
> TRACE StatusLogger Trying to find [log4j2.json] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2.json] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2.json] using
> ClassLoader.getSystemResource().
> TRACE StatusLogger Trying to find [log4j2.jsn] using context class loader
> sun.misc.Launcher$AppClassLoader@4aa298b7.
> TRACE StatusLogger Trying to find [log4j2.jsn] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2.jsn] using
> sun.misc.Launcher$AppClassLoader@4aa298b7 class loader.
> TRACE StatusLogger Trying to find [log4j2.jsn] using
> ClassLoader.getSystemResource().
> TRACE StatusLogger Trying to find [log4j2.xml] using context class loader
> sun.misc.Launcher$AppClassLoader@4aa298b7.
> DEBUG StatusLogger Not in a ServletContext environment, thus not loading
> WebLookup plugin.
> DEBUG StatusLogger Initializing configuration
> XmlConfiguration[location=/Users/cpatrick/working/incubation/unidata-independence/phoenix/log4j2-vscode-very-slow/target/classes/log4j2.xml]
> DEBUG StatusLogger Installed 1 script engine
> DEBUG StatusLogger Oracle Nashorn version: 1.8.0_172, language: ECMAScript,
> threading: Not Thread Safe, compile: true, names: [nashorn, Nashorn, js, JS,
> JavaScript, javascript, ECMAScript, ecmascript], factory class:
> jdk.nashorn.api.scripting.NashornScriptEngineFactory
> DEBUG StatusLogger PluginManager 'Core' found 115 plugins
> DEBUG StatusLogger PluginManager 'Level' found 0 plugins
> DEBUG StatusLogger Building Plugin[name=property,
> class=org.apache.logging.log4j.core.config.Property].
> TRACE StatusLogger TypeConverterRegistry initializing.
> DEBUG StatusLogger PluginManager 'TypeConverter' found 26 plugins
> DEBUG StatusLogger createProperty(name="LOG_PATTERN", value="%d{yyyy-MM-dd
> HH:mm:ss.SSS} %5p %X{mdcData} --- %-40.40c{1.} : %m%n%ex")
> DEBUG StatusLogger Building Plugin[name=properties,
> class=org.apache.logging.log4j.core.config.PropertiesPlugin].
> DEBUG StatusLogger configureSubstitutor(={LOG_PATTERN=%d{yyyy-MM-dd
> HH:mm:ss.SSS} %5p %X{mdcData} --- %-40.40c{1.} : %m%n%ex},
> Configuration(/Users/cpatrick/working/incubation/unidata-independence/phoenix/log4j2-vscode-very-slow/target/classes/log4j2.xml))
> DEBUG StatusLogger PluginManager 'Lookup' found 13 plugins
> DEBUG StatusLogger Building Plugin[name=layout,
> class=org.apache.logging.log4j.core.layout.PatternLayout].
> DEBUG StatusLogger PatternLayout$Builder(pattern="%d{HH:mm:ss.SSS} [%t]
> %-5level %logger{36} - %msg%n", PatternSelector=null,
> Configuration(/Users/cpatrick/working/incubation/unidata-independence/phoenix/log4j2-vscode-very-slow/target/classes/log4j2.xml),
> Replace=null, charset="null", alwaysWriteExceptions="null",
> disableAnsi="null", noConsoleNoAnsi="null", header="null", footer="null")
> DEBUG StatusLogger PluginManager 'Converter' found 42 plugins
> DEBUG StatusLogger Building Plugin[name=appender,
> class=org.apache.logging.log4j.core.appender.ConsoleAppender].
> DEBUG StatusLogger ConsoleAppender$Builder(target="SYSTEM_OUT",
> follow="null", direct="null", bufferedIo="null", bufferSize="null",
> immediateFlush="null", ignoreExceptions="null",
> PatternLayout(%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n),
> name="LogToConsole",
> Configuration(/Users/cpatrick/working/incubation/unidata-independence/phoenix/log4j2-vscode-very-slow/target/classes/log4j2.xml),
> Filter=null)
> DEBUG StatusLogger Starting OutputStreamManager SYSTEM_OUT.false.false
> DEBUG StatusLogger Building Plugin[name=appenders,
> class=org.apache.logging.log4j.core.config.AppendersPlugin].
> DEBUG StatusLogger createAppenders(={LogToConsole})
> DEBUG StatusLogger Building Plugin[name=AppenderRef,
> class=org.apache.logging.log4j.core.config.AppenderRef].
> DEBUG StatusLogger createAppenderRef(ref="LogToConsole", level="null",
> Filter=null)
> DEBUG StatusLogger Building Plugin[name=root,
> class=org.apache.logging.log4j.core.config.LoggerConfig$RootLogger].
> DEBUG StatusLogger createLogger(additivity="null", level="TRACE",
> includeLocation="null", ={LogToConsole}, ={},
> Configuration(/Users/cpatrick/working/incubation/unidata-independence/phoenix/log4j2-vscode-very-slow/target/classes/log4j2.xml),
> Filter=null)
> DEBUG StatusLogger Building Plugin[name=loggers,
> class=org.apache.logging.log4j.core.config.LoggersPlugin].
> DEBUG StatusLogger createLoggers(={root})
> DEBUG StatusLogger Configuration
> XmlConfiguration[location=/Users/cpatrick/working/incubation/unidata-independence/phoenix/log4j2-vscode-very-slow/target/classes/log4j2.xml]
> initialized
> DEBUG StatusLogger Starting configuration
> XmlConfiguration[location=/Users/cpatrick/working/incubation/unidata-independence/phoenix/log4j2-vscode-very-slow/target/classes/log4j2.xml]
> DEBUG StatusLogger Started configuration
> XmlConfiguration[location=/Users/cpatrick/working/incubation/unidata-independence/phoenix/log4j2-vscode-very-slow/target/classes/log4j2.xml]
> OK.
> TRACE StatusLogger Stopping
> org.apache.logging.log4j.core.config.DefaultConfiguration@2133c8f8...
> TRACE StatusLogger DefaultConfiguration notified 1 ReliabilityStrategies that
> config will be stopped.
> TRACE StatusLogger DefaultConfiguration stopping root LoggerConfig.
> TRACE StatusLogger DefaultConfiguration notifying ReliabilityStrategies that
> appenders will be stopped.
> TRACE StatusLogger DefaultConfiguration stopping remaining Appenders.
> DEBUG StatusLogger Shutting down OutputStreamManager SYSTEM_OUT.false.false-1
> DEBUG StatusLogger Shut down OutputStreamManager SYSTEM_OUT.false.false-1,
> all resources released: true
> DEBUG StatusLogger Appender DefaultConsole-1 stopped with status true
> TRACE StatusLogger DefaultConfiguration stopped 1 remaining Appenders.
> TRACE StatusLogger DefaultConfiguration cleaning Appenders from 1
> LoggerConfigs.
> DEBUG StatusLogger Stopped
> org.apache.logging.log4j.core.config.DefaultConfiguration@2133c8f8 OK
> TRACE StatusLogger Reregistering MBeans after reconfigure.
> Selector=org.apache.logging.log4j.core.selector.ClassLoaderContextSelector@f79e
> TRACE StatusLogger Reregistering context (1/1): '4aa298b7'
> org.apache.logging.log4j.core.LoggerContext@480bdb19
> TRACE StatusLogger Unregistering but no MBeans found matching
> 'org.apache.logging.log4j2:type=4aa298b7'
> TRACE StatusLogger Unregistering but no MBeans found matching
> 'org.apache.logging.log4j2:type=4aa298b7,component=StatusLogger'
> TRACE StatusLogger Unregistering but no MBeans found matching
> 'org.apache.logging.log4j2:type=4aa298b7,component=ContextSelector'
> TRACE StatusLogger Unregistering but no MBeans found matching
> 'org.apache.logging.log4j2:type=4aa298b7,component=Loggers,name=*'
> TRACE StatusLogger Unregistering but no MBeans found matching
> 'org.apache.logging.log4j2:type=4aa298b7,component=Appenders,name=*'
> TRACE StatusLogger Unregistering but no MBeans found matching
> 'org.apache.logging.log4j2:type=4aa298b7,component=AsyncAppenders,name=*'
> TRACE StatusLogger Unregistering but no MBeans found matching
> 'org.apache.logging.log4j2:type=4aa298b7,component=AsyncLoggerRingBuffer'
> TRACE StatusLogger Unregistering but no MBeans found matching
> 'org.apache.logging.log4j2:type=4aa298b7,component=Loggers,name=*,subtype=RingBuffer'
> DEBUG StatusLogger Registering MBean org.apache.logging.log4j2:type=4aa298b7
> DEBUG StatusLogger Registering MBean
> org.apache.logging.log4j2:type=4aa298b7,component=StatusLogger
> DEBUG StatusLogger Registering MBean
> org.apache.logging.log4j2:type=4aa298b7,component=ContextSelector
> DEBUG StatusLogger Registering MBean
> org.apache.logging.log4j2:type=4aa298b7,component=Loggers,name=
> DEBUG StatusLogger Registering MBean
> org.apache.logging.log4j2:type=4aa298b7,component=Appenders,name=LogToConsole
> TRACE StatusLogger Using default SystemClock for timestamps.
> TRACE StatusLogger Using DummyNanoClock for nanosecond timestamps.
> DEBUG StatusLogger Reconfiguration complete for context[name=4aa298b7] at URI
> /Users/cpatrick/working/incubation/unidata-independence/phoenix/log4j2-vscode-very-slow/target/classes/log4j2.xml
> (org.apache.logging.log4j.core.LoggerContext@480bdb19) with optional
> ClassLoader: null
> DEBUG StatusLogger Shutdown hook enabled. Registering a new one.
> DEBUG StatusLogger LoggerContext[name=4aa298b7,
> org.apache.logging.log4j.core.LoggerContext@480bdb19] started OK.
> ...logger initialization duration (ms): 5609
> Executing foo() (ms): 1567533456004
> 12:57:36.005 [main] DEBUG patrick.curtis.App - debug
> 12:57:36.008 [main] INFO patrick.curtis.App - info
> 12:57:36.008 [main] WARN patrick.curtis.App - warn
> 12:57:36.008 [main] ERROR patrick.curtis.App - error
> 12:57:36.008 [main] FATAL patrick.curtis.App - fatal
> ...foo() execution duration (ms): 4
> Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 5.657 sec
> DEBUG StatusLogger Stopping LoggerContext[name=4aa298b7,
> org.apache.logging.log4j.core.LoggerContext@480bdb19]
> DEBUG StatusLogger Stopping LoggerContext[name=4aa298b7,
> org.apache.logging.log4j.core.LoggerContext@480bdb19]...
> TRACE StatusLogger Unregistering 1 MBeans:
> [org.apache.logging.log4j2:type=4aa298b7]
> TRACE StatusLogger Unregistering 1 MBeans:
> [org.apache.logging.log4j2:type=4aa298b7,component=StatusLogger]
> TRACE StatusLogger Unregistering 1 MBeans:
> [org.apache.logging.log4j2:type=4aa298b7,component=ContextSelector]
> TRACE StatusLogger Unregistering 1 MBeans:
> [org.apache.logging.log4j2:type=4aa298b7,component=Loggers,name=]
> TRACE StatusLogger Unregistering 1 MBeans:
> [org.apache.logging.log4j2:type=4aa298b7,component=Appenders,name=LogToConsole]
> TRACE StatusLogger Unregistering but no MBeans found matching
> 'org.apache.logging.log4j2:type=4aa298b7,component=AsyncAppenders,name=*'
> TRACE StatusLogger Unregistering but no MBeans found matching
> 'org.apache.logging.log4j2:type=4aa298b7,component=AsyncLoggerRingBuffer'
> TRACE StatusLogger Unregistering but no MBeans found matching
> 'org.apache.logging.log4j2:type=4aa298b7,component=Loggers,name=*,subtype=RingBuffer'
> TRACE StatusLogger Stopping
> XmlConfiguration[location=/Users/cpatrick/working/incubation/unidata-independence/phoenix/log4j2-vscode-very-slow/target/classes/log4j2.xml]...
> TRACE StatusLogger XmlConfiguration notified 2 ReliabilityStrategies that
> config will be stopped.
> TRACE StatusLogger XmlConfiguration stopping 1 LoggerConfigs.
> TRACE StatusLogger XmlConfiguration stopping root LoggerConfig.
> TRACE StatusLogger XmlConfiguration notifying ReliabilityStrategies that
> appenders will be stopped.
> TRACE StatusLogger XmlConfiguration stopping remaining Appenders.
> DEBUG StatusLogger Shutting down OutputStreamManager SYSTEM_OUT.false.false
> DEBUG StatusLogger Shut down OutputStreamManager SYSTEM_OUT.false.false, all
> resources released: true
> DEBUG StatusLogger Appender LogToConsole stopped with status true
> TRACE StatusLogger XmlConfiguration stopped 1 remaining Appenders.
> TRACE StatusLogger XmlConfiguration cleaning Appenders from 2 LoggerConfigs.
> DEBUG StatusLogger Stopped
> XmlConfiguration[location=/Users/cpatrick/working/incubation/unidata-independence/phoenix/log4j2-vscode-very-slow/target/classes/log4j2.xml]
> OK
> DEBUG StatusLogger Stopped LoggerContext[name=4aa298b7,
> org.apache.logging.log4j.core.LoggerContext@480bdb19] with status trueResults
> :Tests run: 1, Failures: 0, Errors: 0, Skipped: 0[INFO]
> ------------------------------------------------------------------------
> [INFO] BUILD SUCCESS
> [INFO]
> ------------------------------------------------------------------------
> [INFO] Total time: 6.920 s
> [INFO] Finished at: 2019-09-03T12:57:36-05:00
> [INFO]
> ------------------------------------------------------------------------
> {code}
>
>
>
>
--
This message was sent by Atlassian Jira
(v8.3.2#803003)
