By Haojiang
During the upgrade of the Java Web application Tomcat from version 7.0.109 to 8.5.93, a puzzling problem was found in the canary environment although everything was verified to be correct in the staging environment: the new log entry was mysteriously "disappearing". This article delves into the troubleshooting and resolution process for this issue, revealing the technical details behind the unusual log entry fault caused by the Tomcat upgrade.
In a recent optimization requirement, the following changes were made to a Java Web application:
These changes are verified to be working correctly in the staging environment, but after the deployment to the canary environment, it was found that no new log entry was generated on the canary machine.
The following troubleshooting directions are available for the problem of missing log entries:
The first three possibilities were ruled out after verification, so now log on to the problematic machine and use Arthas to troubleshoot the code execution logic.
Through the watch command of Arthas (it is recommended to install the arthas idea plug-in to quickly generate commands), you can see that the log class (org.slf4j.impl.Log4jLoggerAdapter) exists, eliminating the possibility that logs are not printed due to the lack of the logger instance.
Since calling the log method does not necessarily print the logs (for example, due to log level settings or execution exceptions), it is necessary to check whether the log method of the log component is executed correctly.
As can be seen from the trace command of Arthas (shown in the following figure), the org.apache.log4j.log() method of the log component is indeed executed and no error is reported.
(Note that the ClassLoader here is ParallelWebappClassLoader, that is, Tomcat's custom ClassLoader.)
Since log4j introduced in the application is a JAR package compiled by 1.4, the trace command recompiles bytecode based on the JavaAgent technology, and Instrumentation only supports bytecode operations for classes compiled by 1.6 or later, the UnsupportedClassVersionError is reported, resulting in the inability to drill down further.
Everything seems to be normal above, but the cause of the problem has emerged here: the Logger objects, Log4jLoggerAdapter in the first step and org.apache.log4j.Logger in the second step, both indicate that the log component currently used is log4j, while this application only has the configuration file of logback.
How is the Logger object Log4jLoggerAdapter generated? By analyzing the LoggerFactory.getLogger() method of the generated Logger object, it is found that the Log4jLoggerAdapter is generated by the org.slf4j.impl.StaticLoggerBinder.
We use the arthas sc -d <classname> command to find out the JAR package from which the StaticLoggerBinder is introduced. Based on the above troubleshooting information, we finally identify the classLoader as the ParallelWebappClassLoader item.
On the problematic machine, the StaticLoggerBinder class belongs to the slfj-log4j12-1.7.7jar package, while on the normal machine, it belongs to the logback-classic-1.2.3.jar as shown in the figure below.
This means that the normal machine uses the StaticLoggerBinder provided by the logback-classic-1.2.3.jar and the problematic machine uses the StaticLoggerBinder provided by the slfj-log4j12-1.7.7. Finally, the generated log components are different.
The problematic machine has two JAR packages, log4j and logback, and both JAR packages have the org.slf4j.impl.StaticLoggerBinder class. For some reason, the StaticLoggerBinder class of log4j (expected to be logback) is finally loaded, thus using the log4j log component, while the application has no log4j-related configuration, resulting in no log output.
Next, we need to analyze this problem to find out its root cause.
To fully answer what causes the final loading of the log4j component, you can put forth the following three key questions in chronological order:
To write a Java program, a Java file needs to be written first, then Javac compiles it into a class bytecode file (or a JAR package), and then JVM's class loader imports it into memory based on the parent delegation mechanism.
For Tomcat's web application, instead of directly running a JAR package through Java, it will first form a WAR package, then deploy the WAR package to the webapp directory of the machine. Finally, when Tomcat runs, it will read and run the files in the webapp directory. The WAR package structure is as follows:
WEB-INF:
-lib // the dependent JAR package
-class // the .class file compiled by the project code
-web.xml // global configuration file
index.html // static resourcesIn the Maven project, you can define dependencies in the pom file, and then use the maven-war-plugin to generate a WAR package. The dependent JAR packages are then stored in the lib directory of the WAR package.
Will all JAR packages defined in pom be stored in the lib folder? Not exactly. For example, packages that are actively excluded in pom or are arbitrated by Maven due to conflicts will be filtered out during packaging. However, since the two logging component dependencies involved here neither conflict nor are excluded, they will both be placed in the lib directory.
<dependency>
<groupId>ch.qos.logback</groupId>
<artifactId>logback-classic</artifactId>
<version>1.2.3</version>
</dependency><dependency>
<groupId>org.slf4j</groupId>
<artifactId>slf4j-log4j12</artifactId>
<version>1.7.7</version>
</dependency>Summary: Since the JAR package coordinates of the two log components are different, they will not be arbitrated due to version conflicts, and will be stored in the WAR package by the Maven packaging plug-in for subsequent use by Tomcat.
It can be seen from the class loading mechanism that the class loading is triggered by bytecode commands such as new, getstatic, putstatic, and invokestatic or reflection calls. Then the class loader will find the class file, import it into the JVM memory, and then complete the class loading process after verification, preparation, parsing, and initialization. There are two key points in this process:
However, in Tomcat, since multiple applications can be deployed, JAR package conflicts may exist in each application. Therefore, it is necessary to break the parent delegation mechanism to achieve JAR package isolation based on the application.
Tomcat will create a ParallelWebappClassLoader instance for each webApp, which prioritizes class loading and delegates the class that cannot be found to the parent class for lookup.
Summary: Some special commands, such as new creating instances and calling reflection methods, will trigger class loading, while in Tomcat applications, classes are loaded first by the ClassLoader customized by Tomcat.
The above analysis shows that there are two different log component JAR packages on the machine, and the class is loaded by Tomcat first. Therefore, it is reasonable to suspect that the new and old machines use different log components because the class loading mechanisms of the Tomcat7 and the Tomcat8 are inconsistent.
ParallelWebappClassLoader source code of Tomcat is analyzed below to find out how the class is loaded. The following is a quick analysis method for troubleshooting. The source code is not analyzed line by line, so only key code snippets are listed to explain the analysis ideas.
Find the class lookup method directly from the ParallelWebappClassLoader, that is, the WebappClassLoaderBase# findClass method, and then locate its internal findClassInternal method.
We are mainly concerned about how Class is generated, so this method will first find snippet 2 and snippet 3. Return directly when entry.loadedClass exists; if it does not exist, initialize based on entry, and pay attention to the key property entry.codeBase during initialization.
The next step is to find out where the entry comes from, locate snippet 1, and then view the findResourceInternal method.
// name is the Fully qualified name of the class
protected Class<?> findClassInternal(String name) throws ClassNotFoundException {
// Snippet 1
ResourceEntry entry = findResourceInternal(name, path, true);
// Snippet 2
Class<?> clazz = entry.loadedClass;
if (clazz != null)
return clazz;
// Snippet 3
try {
clazz = defineClass(name, entry.binaryContent, 0,
entry.binaryContent.length,
new CodeSource(entry.codeBase, entry.certificates));
} catch (UnsupportedClassVersionError ucve) {
throw new UnsupportedClassVersionError(
ucve.getLocalizedMessage() + " " +
sm.getString("webappClassLoader.wrongVersion",
name));
}
entry.loadedClass = clazz;
entry.binaryContent = null;
entry.codeBase = null;
entry.manifest = null;
entry.certificates = null;
}The main concern is how the ResourceEntry is generated.
Snippet 1 shows that we first retrieve from the local cache resourceEntries. What we need to find out is when the cache was written, that is, to find the put method and locate snippet 3. This means that the write was completed in this method, so we need to find the entry initialization position, that is, snippet 2.
As mentioned earlier, the key to the initial definition of the class is codeBase (the physical absolute path of the JAR package), so we need to see where the data in jarRealFiles comes from, so as to locate the addJar method and call the setRepositories method of addJar.
protected ResourceEntry findResourceInternal(final String name, final String path, final boolean manifestRequired) {
// Snippet 1
ResourceEntry entry = resourceEntries.get(path);
if (entry != null) {
return entry;
}
// Snippet 2
try {
entry.codeBase = getURI(jarRealFiles[i]);
entry.source =
UriUtil.buildJarUrl(entry.codeBase.toString(), jarEntryPath);
entry.lastModified = jarRealFiles[i].lastModified();
} catch (MalformedURLException e) {
return null;
}
// Snippet 3
synchronized (resourceEntries) {
// Ensures that all the threads which may be in a race to load
// a particular class all end up with the same ResourceEntry
// instance
ResourceEntry entry2 = resourceEntries.get(path);
if (entry2 == null) {
resourceEntries.put(path, entry);
} else {
entry = entry2;
}
}
}Looking up from the addJar method in snippet 3, we can see that the key parameter destFile of addJar is libDir.list("") in snippet 2, and libPath in snippet 1 is the location where we store JAR packages. So let's see how to implement it in libDir.list.
private void setRepositories() throws IOException {
// Snippet 1
String libPath = "/WEB-INF/lib";
classLoader.setJarPath(libPath);
DirContext libDir = null;
// Looking up directory /WEB-INF/lib in the context
try {
Object object = resources.lookup(libPath);
if (object instanceof DirContext)
libDir = (DirContext) object;
} catch (NamingException e) {
// Silent catch: it's valid that no /WEB-INF/lib collection
// exists
}
// Snippet 2
enumeration = libDir.list("");
while (enumeration.hasMoreElements()) {
NameClassPair ncPair = enumeration.nextElement();
File destFile = new File(destDir, ncPair.getName());
// Snippet 3
try {
JarFile jarFile = JreCompat.getInstance().jarFileNewInstance(destFile);
classLoader.addJar(filename, jarFile, destFile);
} catch (Exception ex) {
// Catch the exception if there is an empty jar file
// Should ignore and continue loading other jar files
// in the dir
}
}
}In the final positioning method, snippet 1 is to find all the file names in the current directory, while the names are sorted in snippet 2 and constructed and returned in snippet 3.
So it can be concluded that the JAR packages in Tomact7 can be sorted by name.
protected List<NamingEntry> list(File file) {
List<NamingEntry> entries = new ArrayList<NamingEntry>();
if (!file.isDirectory())
return entries;
// Snippet 1
String[] names = file.list();
if (names==null) {
/* Some IO error occurred such as bad file permissions.
Prevent a NPE with Arrays.sort(names) */
log.warn(sm.getString("fileResources.listingNull",
file.getAbsolutePath()));
return entries;
}
// Snippet 2
Arrays.sort(names); // Sort alphabetically
NamingEntry entry = null;
// Snippet 3
for (int i = 0; i < names.length; i++) {
File currentFile = new File(file, names[i]);
Object object = null;
if (currentFile.isDirectory()) {
FileDirContext tempContext = new FileDirContext(env);
tempContext.setDocBase(currentFile.getPath());
tempContext.setAllowLinking(getAllowLinking());
object = tempContext;
} else {
object = new FileResource(currentFile);
}
entry = new NamingEntry(names[i], object, NamingEntry.ENTRY);
entries.add(entry);
}
return entries;
}Like Tomcat7, let's first analyze the findClassInternal method, where the key is how to obtain ResourceEntry.
As shown in snippet 1, in Tomcat8, resources.getClassLoaderResource() is called to obtain ResourceEntry.
protected Class<?> findClassInternal(String name) {
checkStateForResourceLoading(name);
if (name == null) {
return null;
}
String path = binaryNameToPath(name, true);
ResourceEntry entry = resourceEntries.get(path);
WebResource resource = null;
if (entry == null) {
// Snippet 1
resource = resources.getClassLoaderResource(path);
if (!resource.exists()) {
return null;
}
entry = new ResourceEntry();
entry.lastModified = resource.getLastModified();
// Add the entry in the local resource repository
synchronized (resourceEntries) {
// Ensures that all the threads which may be in a race to load
// a particular class all end up with the same ResourceEntry
// instance
ResourceEntry entry2 = resourceEntries.get(path);
if (entry2 == null) {
resourceEntries.put(path, entry);
} else {
entry = entry2;
}
}
}In this step, something seems not right. The storage path of the JAR package is /WEB-INF/lib, but here it is /WEB-INF/classes. What's wrong with the analysis? Let’s dig deeper!
@Override
public WebResource getClassLoaderResource(String path) {
return getResource("/WEB-INF/classes" + path, true, true);
}The returned object WebResource is generated by the getResource method of webResourceSet. The getResource method searches for files based on the path. Obviously, it is necessary to start analyzing the webResourceSet to find out how allResources and webResourceSet are generated.
protected final WebResource getResourceInternal(String path,boolean useClassLoaderResources) {
WebResource result = null;
WebResource virtual = null;
WebResource mainEmpty = null;
for (List<WebResourceSet> list : allResources) {
for (WebResourceSet webResourceSet : list) {
if (!useClassLoaderResources && !webResourceSet.getClassLoaderOnly() ||
useClassLoaderResources && !webResourceSet.getStaticOnly()) {
result = webResourceSet.getResource(path);
if (result.exists()) {
return result;
}
if (virtual == null) {
if (result.isVirtual()) {
virtual = result;
} else if (main.equals(webResourceSet)) {
mainEmpty = result;
}
}
}
}
}
// Use the first virtual result if no real result was found
if (virtual != null) {
return virtual;
}
// Default is empty resource in main resources
return mainEmpty;
}You can see that the array is initially empty, and the first element of the allResources array is preResources, which means that in the preceding search, preResources is queried first, followed by mainResources. The next step is to find out when to add data to these Resources.
private final List<WebResourceSet> preResources = new ArrayList<>();
private final List<WebResourceSet> classResources = new ArrayList<>();
private final List<WebResourceSet> jarResources = new ArrayList<>();
private final List<WebResourceSet> postResources = new ArrayList<>();
private final List<WebResourceSet> mainResources = new ArrayList<>();
private WebResourceSet main;
private final List<List<WebResourceSet>> allResources =
new ArrayList<>();
{
allResources.add(preResources);
allResources.add(mainResources);
allResources.add(classResources);
allResources.add(jarResources);
allResources.add(postResources);
}By searching preResources globally, locate the createWebResourceSet method. Here, WebResourceSet creates dependent input parameters, so find the source of this method call.
public void createWebResourceSet(ResourceSetType type, String webAppMount,
String base, String archivePath, String internalPath) {
List<WebResourceSet> resourceList;
WebResourceSet resourceSet;
switch (type) {
case PRE:
resourceList = preResources;
break;
case CLASSES_JAR:
resourceList = classResources;
break;
case RESOURCE_JAR:
resourceList = jarResources;
break;
case POST:
resourceList = postResources;
break;
default:
throw new IllegalArgumentException(
sm.getString("standardRoot.createUnknownType", type));
}
resourceSet = new JarWarResourceSet(this, webAppMount, base, archivePath, internalPath);
resourceList.add(resourceSet);Locate the caller of the createWebResourceSet method and see /WEB-INF/lib. In addition, the input parameter webAppMount is set to /WEB-INF/classes, which is a mount path (similar to a virtual directory). The actual physical path is possibleJar.getURL().
Before analyzing the listResources method, it is necessary to see when the processWebInfLib method is called.
private void processWebInfLib() {
WebResource[] possibleJars = listResources("/WEB-INF/lib", false);
for (WebResource possibleJar : possibleJars) {
if (possibleJar.isFile() && possibleJar.getName().endsWith(".jar")) {
createWebResourceSet(ResourceSetType.CLASSES_JAR,
"/WEB-INF/classes", possibleJar.getURL(), "/");
}
}
}You can see that processWebInfLib is called in a startup method. Note that in snippet 1 mainResources adds a main object, which is an instance of the DirResourceSet class. This means that allResources is not empty now.
@Override
protected void startInternal() throws LifecycleException {
mainResources.clear();
// Snippet 1
main = createMainResourceSet();
mainResources.add(main);
for (List<WebResourceSet> list : allResources) {
// Skip class resources since they are started below
if (list != classResources) {
for (WebResourceSet webResourceSet : list) {
webResourceSet.start();
}
}
}
// This has to be called after the other resources have been started
// else it won't find all the matching resources
processWebInfLib();
// Need to start the newly found resources
for (WebResourceSet classResource : classResources) {
classResource.start();
}
cache.enforceObjectMaxSizeLimit();
setState(LifecycleState.STARTING);
}From the preceding analysis, we know that there is a DirContenxtSet instance under the mainResurces array in allResources. Therefore, webResourceSet.list(path) can locate the DirResourceSet class.
private String[] list(String path, boolean validate) {
if (validate) {
path = validate(path);
}
// Set because we don't want duplicates
// LinkedHashSet to retain the order. It is the order of the
// WebResourceSet that matters but it is simpler to retain the order
// over all of the JARs.
HashSet<String> result = new LinkedHashSet<>();
for (List<WebResourceSet> list : allResources) {
for (WebResourceSet webResourceSet : list) {
if (!webResourceSet.getClassLoaderOnly()) {
String[] entries = webResourceSet.list(path);
for (String entry : entries) {
result.add(entry);
}
}
}
}
return result.toArray(new String[result.size()]);
}Finally, the class is located, and the webAppMout of DirResourceSet is "/", so enter the logic of snippet 1. The file.list() method directly returns all JAR package paths under /WEB-INF/lib (instead of using Arrays.sort to sort like Tomcat7).
Tomcat8 imports all file paths in the lib directory into WebResourceSet when the web application starts, and then performs class lookup directly in WebResourceSet to avoid calling the system file.list method every time.
public String[] list(String path) {
checkPath(path);
String webAppMount = getWebAppMount();
if (path.startsWith(webAppMount)) {
File f = file(path.substring(webAppMount.length()), true);
if (f == null) {
return EMPTY_STRING_ARRAY;
}
// Snippet 1
String[] result = f.list();
if (result == null) {
return EMPTY_STRING_ARRAY;
} else {
return result;
}
} else {
if (!path.endsWith("/")) {
path = path + "/";
}
if (webAppMount.startsWith(path)) {
int i = webAppMount.indexOf('/', path.length());
if (i == -1) {
return new String[] {webAppMount.substring(path.length())};
} else {
return new String[] {
webAppMount.substring(path.length(), i)};
}
}
return EMPTY_STRING_ARRAY;
}
}Summary: The list of imported JAR packages in Tomcat7 is sorted in alphabetical order based on the names of the JAR packages, while the list of JAR packages obtained by Tomcat8 is not sorted. Therefore, when Tomcat7 loads classes on different machines, it can locate the same JAR package every time, which cannot be guaranteed in Tomcat8.
It can be seen from the above that Tomcat8 directly calls file.list() to obtain the file list, while list is a local method. You can go to GitHub to view the openJdk8 source code (if you don't know much about C language, you can use chatGPT to understand the code logic).
It can be seen that the directory is traversed through readdir64_r, while the implementation of readdir64_r is related to the system. For example, the ext4 file system caches directory files through hashTree, which does not guarantee the sequential order of the file list.
From the above analysis, it can be seen that because log4j and logback have different coordinates (but both have the org.slf4j.impl.StaticLoggerBinder class), their JAR packages will be stored in the webapp directory.
When Tomcat7 loads the org.slf4j.impl.StaticLoggerBinder class, it will sort the JAR packages by name before searching (logback will be ranked first by name), so it can load this class from logback every time.
However, Tomcat8 does not automatically sort the class, which depends entirely on the JAR package list returned by the file system. At this time, the order is not guaranteed. As a result, Tomcat8 cannot ensure loading the class from logback every time.
The three key issues identified in the root cause analysis are actually the entry points for the corresponding solutions.
An important reason is that the same class exists in different JAR packages, resulting in implicit conflicts. So you can manually arrange packages to resolve conflicts.
You can use the manven-enforcer plug-in to scan all JAR package conflicts and JAR packages with duplicate classes.
The direct cause of the problem analyzed above is the difference in the ClassLoader logic between different versions of Tomcat, so we can rewrite or customize ClassLoader to customize the class loading logic.
If you do not want to modify the entire ClassLoader as in the class loading phase, you can choose the following solutions when selecting the key JAR package:
The first solution is to return to Tomcat7. Based on the mechanism of loading JAR packages in an orderly manner, all machines perform the same. If problems are found in the offline environment, the packages will be arranged on demand.
The second solution is that Tomcat8 can support specifying the JAR package to be used preferentially during class loading: define PreResources in Tomcat's Context.xml (the analysis of Tomcat8 in root cause analysis shows that PreResources is traversed first during class searching).
<Resources>
<PreResources base="D:\Projects\lib\library1.jar"
className="org.apache.catalina.webresources.JarWarResourceSet"
webAppMount="/WEB-INF/classes"/>
</Resources>This article records in detail the troubleshooting and resolution process of a log entry fault caused by a Tomcat upgrade, and deeply analyzes the background, specific phenomena, troubleshooting steps, root causes, and solutions of the problem, providing valuable reference and solution ideas for developers who encounter similar problems. This experience not only reveals the compatibility issues that may be encountered during software upgrades but also emphasizes the importance of understanding the underlying technology stack of the application, such as the class loading mechanism and the working principle of the logging framework.
[01] Detailed Explanation of JVM Bytecode
https://blog.csdn.net/jifashihan/article/details/141420420
[02] Principles of JavaAgent Technology
https://www.jianshu.com/p/4b5b533385f7
[03] Parent Delegation Model
https://www.jianshu.com/p/5e0441cd2d4c
[04] Maven's Arbitration Mechanism
https://baijiahao.baidu.com/s?id=1745192284330030901&wfr=spider&for=pc
[05] Understanding Java Class Loading Mechanism
https://blog.csdn.net/BarackYoung/article/details/137060856
[06] Tomcat's Class Loading Mechanism
https://cloud.tencent.com/developer/article/2089600
[07] JAR Package Loading Order in Tomcat7 and Tomcat8
https://www.cnblogs.com/zjdxr-up/p/17139374.html
[08] Differences between Common Logging Frameworks (Log4j, SLF4J, and Logback)
https://cloud.tencent.com/developer/article/1400334
Disclaimer: The views expressed herein are for reference only and don't necessarily represent the official views of Alibaba Cloud.
1,046 posts | 257 followers
FollowAlibaba Clouder - November 23, 2020
Alibaba Clouder - November 18, 2019
Alibaba Cloud Serverless - November 27, 2023
Alibaba Developer - September 6, 2021
Alibaba Clouder - June 15, 2020
Alibaba Developer - September 23, 2020
1,046 posts | 257 followers
Follow
Web Hosting Solution
Explore Web Hosting solutions that can power your personal website or empower your online business.
Learn More
YiDA Low-code Development Platform
A low-code development platform to make work easier
Learn More
Web Hosting
Explore how our Web Hosting solutions help small and medium sized companies power their websites and online businesses.
Learn More
mPaaS
Help enterprises build high-quality, stable mobile apps
Learn MoreMore Posts by Alibaba Cloud Community