I occasionally used a version of Tomcat-Native DLL that JVM failed to initialize. The error was logged to stderr, but to none of our log files. Steps to reproduce with 8.0.14 on Windows with JDK 7u67: 1. Get a wrong version of tcnative-1.dll and put it into %CATALINA_HOME%/bin directory. I erroneously used a x64 DLL with a x86 JDK. 2. Start Tomcat and log output into a file: cd bin catalina.bat run >catalina.out 2>&1 3. Stop Tomcat Ctrl+C or catalina.bat stop 4. Actual: An error (cited below) was logged onto console (catalina.out) but it is not present in catalina.2014-09-25.log file. The only relevant message in catalina.2014-09-25.log was "The APR based Apache Tomcat Native library <...> was not found on the java.library.path: <...>. Expected: A properly logged error. Looking in the source code, 1) In AprLifecycleListener.init() the Throwable is caught but not logged. 2) The exception is printed by org.apache.tomcat.jni.Library.Library() constructor. The code looks like the following: [[[ String name = System.mapLibraryName(NAMES[i]); String path = System.getProperty("java.library.path"); String sep = System.getProperty("path.separator"); String [] paths = path.split(sep); for (int j=0; j<paths.length; j++) { java.io.File fd = new java.io.File(paths[j] , name); if (fd.exists()) { t.printStackTrace(); } } if ( i > 0) err.append(", "); err.append(t.getMessage()); <...> if (!loaded) { err.append('('); err.append(System.getProperty("java.library.path")); err.append(')'); throw new UnsatisfiedLinkError(err.toString()); } ]]] The loop with "fd.exists()" does essentially the same thing that JRE itself is doing in loadLibrary() to locate the library file before actually trying to load it. Thoughts on possible improvement: =================================== A. Treat the case when "fd.exists()" as fatal and rethrow original exception. This will change behaviour in case when both "tcnative-1" and "libtcnative-1" libraries are present in "java.library.path" directories and the first library fails to load while the second one succeeds. With the current code it will print an error for the first library and may silently successfully load the second one. With the change that I am proposing it will fail with the first library without trying the second one. I say that configuration with both libraries being present is unlikely, and as it was printing an error for the first library I say that such configuration is a broken one. Rethrowing original exception will provide better diagnostics (if AprLifecycleListener is modified to log it) and will remove printing to System.err. B. Replace "throw new UnsatisfiedLinkError(err.toString());" with a custom Error class e.g. LibraryNotFoundError extends UnsatisfiedLinkError. - Include original exceptions and library names into LibraryNotFoundError. - Use this class in AprLifecycleListener to discern between UnsatisfiedLinkError from failed attempt to load a library versus the common "library does not exist" scenario. In the former case, log it as a warning. In the latter case print original exceptions if debug logging is enabled. The usual informational message follows. C. Simplify AprLifecycleListener class and call Library.initialize(null) directly without relying on reflection. There are already references to the fields such as Library.APR_MAJOR_VERSION further in the code. There is no point in using reflection is this case. In the unlikely case that tomcat-jni.jar is not on classpath, AprLifecycleListener should not be present in server.xml as well. In this case Connector.<init> will call AprLifecycleListener.isAprAvailable() but the call to init() will not be performed. It should succeed even if Library class is not on classpath. For reference, the error message with 8.0.14 (with some path censoring) was: ======================== [[[ java.lang.UnsatisfiedLinkError: <CATALINA_HOME>\bin\tcnative-1.dll: Can't load AMD 64-bit .dll on a IA 32-bit platform at java.lang.ClassLoader$NativeLibrary.load(Native Method) at java.lang.ClassLoader.loadLibrary1(ClassLoader.java:1965) at java.lang.ClassLoader.loadLibrary0(ClassLoader.java:1890) at java.lang.ClassLoader.loadLibrary(ClassLoader.java:1880) at java.lang.Runtime.loadLibrary0(Runtime.java:849) at java.lang.System.loadLibrary(System.java:1088) at org.apache.tomcat.jni.Library.<init>(Library.java:40) at org.apache.tomcat.jni.Library.initialize(Library.java:172) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at org.apache.catalina.core.AprLifecycleListener.init(AprLifecycleListener.java:203) at org.apache.catalina.core.AprLifecycleListener.isAprAvailable(AprLifecycleListener.java:105) at org.apache.catalina.connector.Connector.setProtocol(Connector.java:564) at org.apache.catalina.connector.Connector.<init>(Connector.java:66) at org.apache.catalina.startup.ConnectorCreateRule.begin(ConnectorCreateRule.java:62) ... ]]]
+0 on proposal A; I'm not sure it matters all that much. But if there is a conflicting set of libraries, it might be better to fail fast rather than confuse the user with both an error message *and* a successfully-loaded (alternate) library. I'm not sure that both libtcnative-1 *and* tcnative-1 would be tried on any system though (does win32 do this?). +1 on both proposals B and C
Created attachment 32453 [details] The attached patch has fixes for both A and B points. I have modified AprLifecycleListener.java and Library.java to fix the issue. Added a new file "LibraryNotFoundError.java" in "org.apache.tomcat.jni" package. Added two new strings in "LocalStrings.properties" file located in "org.apache.catalina.core" package. I do not know the Locale languages like Japaneese and French, so did not add the new strings in other Locale property files. I tested the fix and attached the log files as well. I provided the fix based on the comments provided in the issue. I did not implement the 3rd point(C) yet.
Sorry, I could not attach the log files. This portal is not allowing me to attach the logs which are generated with the fix.
Thanks for the patch! Some comments: 1. In AprLifecycleListener.java, there is no need to log the error both at WARN and DEBUG levels. WARN is sufficient. 2. s/Commenetd/Commented/ 3. Add Javadoc for the Exception class.
@Chris the difference with WARN and DEBUG is that DEBUG includes the stack trace. I'd say if debug is not enabled, log at WARN, else log at DEBUG so you never get more than one message. Some more comments. 1. Check line length. Some appear to be over to 100 char limit for code lines. 2. Don't comment out code to disable it. Delete it. Just think how many lines must have been deleted/changed in the last 10+ years. If we want to look at an old version we'll use the version control system tools. We do not want to be wading through reams of commented out code. 3. Try not to mix code formatting changes (e.g adding blank lines) with functional changes.
(In reply to Mark Thomas from comment #5) > @Chris the difference with WARN and DEBUG is that DEBUG includes the stack > trace. I'd say if debug is not enabled, log at WARN, else log at DEBUG so > you never get more than one message. ACK. I hadn't noticed the stack trace. Vin, please ignore my comment about WARN versus DEBUG.
I updated the code as per your comments. Generated java doc for LibraryNotFoundError.java class and added to patch. Now the patch is of 100KB size. I attached the updated patch. Please review it.
Created attachment 32460 [details] Updated patch with suggested comments Please let me know if anything is missing.
(In reply to VIN from comment #8) > Created attachment 32460 [details] > Updated patch with suggested comments > > Please let me know if anything is missing. The doc/*.html files should not be in the patch... they are auto-generated from the xml files elsewhere. In AprLifecycleListener near line 208, instead of catching Throwable and then checking for LibraryNotFoundError and UnsatisfiedLinkError, why not add catch clauses and leave the default action in catch(Throwable)? I think this will be a better way to do things. I'm not sure what the implications are, but the old (and default case) code adds the log message to initInfoLogMessages while the new code performs logging directly. Is there a reason to prefer one over the other?
Some further feedback 1. Indents should be with 4 spaces not tabs. 2. In LibraryNotFoundError libraryName is better than nameOfLibrary 3. Improvement B requested name*s* of the libraries, not just one. 4. The patch always throws an Exception on the first name. There is never a chance to check the second name. 5. Improvement A is not addressed. 6. Javadoc for LibraryNotFoundError adds no value. Yes, neither does much of the Javadoc in that package but that is not a reason to continue in the same direction. 7. Log messages inr AprLifecycleListener.init should not be made directly to the logger. Check the svn history for that file to find out why. In applying and reviewing the patch I have fixed the various issues so I should be committing this fairly soon. Don't be concerned about how much has been changed. The first patch I offered was unrecognisable by the time Bill had finished with it. Your first patch is a lot better than my first patch.
This has been fixed in trunk, 8.0.x (for 8.0.19 onwards) and 7.0.x (for 7.0.60 onwards).
Adding debug and error messages to initInfoLogMessages list results in them being printed at INFO level. It is hard to discern them from other INFO messages. I think that in those cases they should just be logged immediately, without postponing the logging. I'll update the fix.
Those messages are postponed to avoid them appearing before the version info etc. I viewed logging them at INFO as less bad than logging them before the version info. The ideal would be to track the level along with the message in the postponed logging.
(In reply to Mark Thomas from comment #13) Version info is just some information. I think that error messages (and debug ones) are more helpful when they are timely. I agree that it can be a matter of taste, though. Updated the fix in r1659427,-28,-29, r1659431 (for 8.0.19 onwards, 7.0.60 onwards).
(In reply to Christopher Schultz from comment #9) > (In reply to VIN from comment #8) > > Created attachment 32460 [details] > > Updated patch with suggested comments > > > > Please let me know if anything is missing. > > The doc/*.html files should not be in the patch... they are auto-generated > from the xml files elsewhere. Hi Chris, I generated the Javadoc from Eclipse which generated those many HTML files. I was not aware that we should not be putting all those files into patch. Can you help explain me on what is the best approach to generate the java doc and what files need to be uploaded in generated files? > In AprLifecycleListener near line 208, instead of catching Throwable and > then checking for LibraryNotFoundError and UnsatisfiedLinkError, why not add > catch clauses and leave the default action in catch(Throwable)? I think this > will be a better way to do things. I have gone through multiple links to understand between catching an exception vs catching Throwable and my findings are: When we catch Exception, all sub classes of exception will be caught but ERRORS will not be part of them. (ERRORS are serious problems like MemoryOutOfBound where JVM may need to shutdown). Throwable is super class of all Exceptions and Errors and when we catch Throwable all the Errors also will be caught. But from JAVA Doc: An Error is a subclass of Throwable that indicates serious problems that a reasonable application should not try to catch. Most such errors are abnormal conditions. The ThreadDeath error, though a "normal" condition, is also a subclass of Error because most applications should not try to catch it. It means applications should not try to catch Throwable. I have seen many places in our Tomcat application, catching the Throwable. In this regard, can you help me to understand why do we use Throwable and where can it be used in general? > > I'm not sure what the implications are, but the old (and default case) code > adds the log message to initInfoLogMessages while the new code performs > logging directly. Is there a reason to prefer one over the other? The initInfoLogMessages holds only the INFO messages, but as per the bug request we need to log the exception as warning. Hence i did not add it to initInfoLogMessages.
(In reply to Mark Thomas from comment #10) > Some further feedback > > 1. Indents should be with 4 spaces not tabs. Hi Mark, I changed the code using Eclipse editor which by default adds tab as indent. Next time on wards i will open the changed code in notepad and check the indents. > > 2. In LibraryNotFoundError libraryName is better than nameOfLibrary Sure, Thanks. > > 3. Improvement B requested name*s* of the libraries, not just one. As per the enhancement mentioned in the request, Tomcat code should not try to load the second library when the first library failed to load. So I thought there is no point in maintaining array of library names. Please correct me if my understanding is wrong. > > 4. The patch always throws an Exception on the first name. There is never a > chance to check the second name. As per the enhancement mentioned in request, code should not try load the second library. That's why I intentionally returned the exception (throw t;). Please correct me if my understanding is wrong. > > 5. Improvement A is not addressed. A. Treat the case when "fd.exists()" as fatal and rethrow original exception. I throw the original exception back to AprLifeCycleListener.java as mentioned. In Library.java, i am throwing this and in AprLifecycleListener.java, I logged this exception as warning. Forgot to mark it as Fatal :) throw new LibraryNotFoundError(name, err.toString()); > > 6. Javadoc for LibraryNotFoundError adds no value. Yes, neither does much of > the Javadoc in that package but that is not a reason to continue in the same > direction. > > 7. Log messages inr AprLifecycleListener.init should not be made directly to > the logger. Check the svn history for that file to find out why. Sure, I will check. I found only initInfoLogMessages variable in AprLifecycleListener.java, did not find the Fatal or Warning variable so i felt no other way than directly print to the log file by log.warn(). > > In applying and reviewing the patch I have fixed the various issues so I > should be committing this fairly soon. > > Don't be concerned about how much has been changed. The first patch I > offered was unrecognisable by the time Bill had finished with it. Your first > patch is a lot better than my first patch. Do we have any guidelines document so that i can go through and follow accordingly? Thanks so much for your time :)
(In reply to VIN from comment #16) > (In reply to Mark Thomas from comment #10) > > Some further feedback > > > > 1. Indents should be with 4 spaces not tabs. > Hi Mark, > I changed the code using Eclipse editor which by default adds tab as > indent. Next time on wards i will open the changed code in notepad and check > the indents. > > > > > 2. In LibraryNotFoundError libraryName is better than nameOfLibrary > Sure, Thanks. > > > > 3. Improvement B requested name*s* of the libraries, not just one. > As per the enhancement mentioned in the request, Tomcat code should not > try to load the second library when the first library failed to load. So I > thought there is no point in maintaining array of library names. > > Please correct me if my understanding is wrong. > > > > > 4. The patch always throws an Exception on the first name. There is never a > > chance to check the second name. > > As per the enhancement mentioned in request, code should not try load > the second library. That's why I intentionally returned the exception (throw > t;). > > Please correct me if my understanding is wrong. > > > > > > 5. Improvement A is not addressed. > A. Treat the case when "fd.exists()" as fatal and rethrow original > exception. > I throw the original exception back to AprLifeCycleListener.java as > mentioned. > > In Library.java, i am throwing this and in AprLifecycleListener.java, I > logged this exception as warning. Forgot to mark it as Fatal :) > > throw new LibraryNotFoundError(name, err.toString()); > > > > > 6. Javadoc for LibraryNotFoundError adds no value. Yes, neither does much of > > the Javadoc in that package but that is not a reason to continue in the same > > direction. > > > > 7. Log messages inr AprLifecycleListener.init should not be made directly to > > the logger. Check the svn history for that file to find out why. > > Sure, I will check. I found only initInfoLogMessages variable in > AprLifecycleListener.java, did not find the Fatal or Warning variable so i > felt no other way than directly print to the log file by log.warn(). > > > > > In applying and reviewing the patch I have fixed the various issues so I > > should be committing this fairly soon. > > > > Don't be concerned about how much has been changed. The first patch I > > offered was unrecognisable by the time Bill had finished with it. Your first > > patch is a lot better than my first patch. > > > Do we have any guidelines document so that i can go through and follow > accordingly? > > Thanks so much for your time :) I have gone through the fixed code. It is nice and simple. One query is: In AprLifecycleListener.java, the LibraryNotFound exception is added to initInfiLogMessages variable. I suspect it would print the error as INFO.
(In reply to Konstantin Kolinko from comment #14) > > Version info is just some information. I think that error messages (and > debug ones) are more helpful when they are timely. I agree that it can be a > matter of taste, though. I'll see how much the ordering bugs me. If it bugs me enough, I'll do something about it. The delay is only between the loading of the Listener class and init() being called so it isn't a big issue. The messages would still appear - just after the version info rather than before it.
(In reply to VIN from comment #16) > (In reply to Mark Thomas from comment #10) > > Some further feedback > > > > 1. Indents should be with 4 spaces not tabs. > Hi Mark, > I changed the code using Eclipse editor which by default adds tab as > indent. Next time on wards i will open the changed code in notepad and check > the indents. You can change this per project in Eclipse. > > 3. Improvement B requested name*s* of the libraries, not just one. > As per the enhancement mentioned in the request, Tomcat code should not > try to load the second library when the first library failed to load. So I > thought there is no point in maintaining array of library names. > > Please correct me if my understanding is wrong. There is a difference between the library being found and not loading (error immediately) vs the library not being found and not loading (try the next name). If all names fail we still need to log all names. > > 4. The patch always throws an Exception on the first name. There is never a > > chance to check the second name. > > As per the enhancement mentioned in request, code should not try load > the second library. That's why I intentionally returned the exception (throw > t;). > > Please correct me if my understanding is wrong. See above. > > 5. Improvement A is not addressed. I meant C.
(In reply to Mark Thomas from comment #19) > (In reply to VIN from comment #16) > > (In reply to Mark Thomas from comment #10) > > > Some further feedback > > > > > > 1. Indents should be with 4 spaces not tabs. > > Hi Mark, > > I changed the code using Eclipse editor which by default adds tab as > > indent. Next time on wards i will open the changed code in notepad and check > > the indents. > > You can change this per project in Eclipse. > > > > 3. Improvement B requested name*s* of the libraries, not just one. > > As per the enhancement mentioned in the request, Tomcat code should not > > try to load the second library when the first library failed to load. So I > > thought there is no point in maintaining array of library names. > > > > Please correct me if my understanding is wrong. > > There is a difference between the library being found and not loading (error > immediately) vs the library not being found and not loading (try the next > name). If all names fail we still need to log all names. > > > > 4. The patch always throws an Exception on the first name. There is never a > > > chance to check the second name. > > > > As per the enhancement mentioned in request, code should not try load > > the second library. That's why I intentionally returned the exception (throw > > t;). > > > > Please correct me if my understanding is wrong. > > See above. > > > > 5. Improvement A is not addressed. > > I meant C. Got you Mark. Thanks. Do we have any guidelines document so that i can go through and follow while coding?
http://tomcat.apache.org/tomcat-8.0-doc/building.html#Building_with_Eclipse
(In reply to Konstantin Kolinko from comment #21) > http://tomcat.apache.org/tomcat-8.0-doc/building.html#Building_with_Eclipse Got it. Thanks.