Allow the logger name mismatch detector to work even if security manager creation is disabled.

[adorokhine]

Implemented by falling back to slower exception-based method if this happens.

Fixes bug SLF4J-324.

[adorokhine]

@mattbishop @ceki

I don't think there's any other efficient way to get a backtrace if we can't construct a SecurityManager.

Fundamentally, all we need is to call SecurityManager#getClassContext, but we can't do that without constructing a class in SecurityManager's inheritance hierarchy because it's protected. SecurityManager construction might be disabled by an existing SecurityManager: http://grepcode.com/file/repository.grepcode.com/java/root/jdk/openjdk/6-b14/java/lang/SecurityManager.java#299

Under the hood, SecurityManager simply calls JVM_GetClassContext in JNI: https://code.openhub.net/file?fid=DvdXh1aTTWSBu1zKlsh5SA_JEnQ&cid=9CbxgfzUr7o&s=JVM_GetClassContext&fp=309993&mp,=1&ml=1&me=1&md=1&projSelected=true#L77

But there's no other public callers of that function in hotspot, and I definitely don't want to start adding JNI to slf4j.

The functionality of getting the class of the caller is directly implemented in sun.reflection.Reflection#getCallerClass: http://grepcode.com/file/repository.grepcode.com/java/root/jdk/openjdk/6-b14/sun/reflect/Reflection.java#64

Sadly, the sun.* packages are not meant for public use and won't help us when running under other JVMs.

So I don't see any other solutions than to fall back to exception-based stack traces.

Testing on my machine with a stack depth of ~17 frames and 100,000 calls, I get 12.3 microseconds per trace with the new exception implementation, and 2.2 microseconds per trace with the SecurityManager approach. I can't find any better solutions to fall back to though, so I hope this is okay.

[mattbishop]

I had the thought to implement a SecurityManager wrapper that did not extend SecurityManager so it could call the protected methods on the existing SecurityManager. However it would need to live in java.lang, and I don't think we can create classes in that package.

It might be interesting to see if you can relax access to the existing security manager's method to get the current class. Look at Method.setAccessible()

[adorokhine]

Hi, Matt,

I had considered this, but the problem is that access to Method.setAccessible is also controlled by the security manager. Chances are, if the system is locked down enough that we can't create a new security manager, it's also locked down enough that we can't increase visibility of restricted methods through reflection.

I could add it as a fallback path if you like, but I don't expect it to be usable very often.

You're right that we can't create our own files in the java.lang package; that's locked down.

Cheers, Alex. On Apr 27, 2015 10:00 AM, "Matt Bishop" [email protected] wrote:

I had the thought to implement a SecurityManager wrapper that did not extend SecurityManager so it could call the protected methods on the existing SecurityManager. However it would need to live in java.lang, and I don't think we can create classes in that package.

It might be interesting to see if you can relax access to the existing security manager's method to get the current class. Look at Method.setAccessible()

— Reply to this email directly or view it on GitHub https://github.com/qos-ch/slf4j/pull/115#issuecomment-96741064.

[adorokhine]

Friendly ping on this PR.

[adorokhine]

@ceki @mattbishop Friendly bump on this PR; I would like to get this bug fixed. Any concerns or suggestions on the proposed implementation?

[mattbishop]

I'm not crazy about the failure flag.

Also the security manager API wants one to use AccessController.doPrivileged() to do things that might trip up the security manager. Most code that needs to be worried about the security manager follows this kind of idiom:

if (System.getSecurityManager() == null) {
  //no Security Manager
  //do your thing
} else {
  AccessController.doPrivileged(new PrivilegedAction() {
    //do your thing
  });
}

[adorokhine]

@mattbishop Thanks for the feedback. I've never worked with the security manager so I really appreciate it.

I've wrapped the code in a doPrivileged block and removed the failure flag. Please take another look?

[mattbishop]

Almost there, thanks for the effort!

[adorokhine]

@mattbishop Sorry for the hold-up and thanks for the detailed review!

I've refactored this PR a bit so that the implementation of caller finder implements an interface and can be swapped. I think this makes it easier to write alternate implementations in the future, and also it easier to unit test, so I've added a bunch of new unit tests for both implementations.

I've done my best to address your comments as well. Please take a look and let me know if you like the new design!

[mattbishop]

I'm ready to merge this, any objections?

[adorokhine]

@mattbishop sounds good to me; let's do it! :)

[ceki]

Please allow me to review before merging.

[adorokhine]

@ceki Sure, just let me know what you would like to see.

[adorokhine]

@ceki @mattbishop Could you please take a look or merge? It's been almost 8 weeks since the last comment! :(

[adorokhine]

@mattbishop we haven't heard from Ceki for 2 1/2 months... this PR has been open for almost 5 months and the bug has existed for 9 months. Is there anything I can do? What do you recommend?

[ceki]

I am currently traveling but I promise to have a look this saturday and come back to you.

[adorokhine]

@ceki Thanks! :)

[adorokhine]

@ceki Bug 324 just got another comment from someone broken by this issue... :(

[ceki]

I went for a minimalist fix. In presence of a SecurityManager preventing the creation of a SecurityManager instance in o.s.helpers.Util, the code simply skips mismatch detection.

The code with a fallback to another method of computing the caller class would be necessary if the logger name was computed dynamically. However, at present, slf4j only performs name mismatch verification and only if explicitly asked to do so.

[adorokhine]

@ceki thanks for the quick fix. However, I don't think this is the right long-term fix for this feature.

The whole point of this check is a temporary stepping stone to an API for dynamically named loggers: LoggerFactory.getLogger().

This API has to work in all conditions, including the presence of a security manager.

I still think this pull request is the right way to go. I have rebased it to HEAD; could you please take a look and let me know your thoughts? If you have any concerns with the current implementation, please let me know. And if you have changed your mind on dynamically named loggers, please tell me and I will just remove all this code completely. It adds a whole bunch of complexity, so if we can't get dynamically named loggers out of it, I don't think it has a lot of value versus its maintenance.

Otherwise, mind taking another look at this PR?

Thanks a lot! Alex

[mattbishop]

Guava 19 released last month with an interesting new feature--LazyStackTrace. Alex, you should have a look and see how they did that. It might be useful here where we want to find the calling class without the full cost of building a stack trace: https://github.com/google/guava/wiki/Release19

[mattbishop]

To clarify, I am not suggesting we use Guava here, but instead look at how they implemented it and see if you can implement Logger.getLogger() in a similar fashion.

[adorokhine]

Thanks Matt for the interesting pointer! I will take a look at LazyStackTrace this week.

On 12 January 2016 at 10:40, Matt Bishop [email protected] wrote:

To clarify, I am not suggesting we use Guava here, but instead look at how they implemented it and see if you can implement Logger.getLogger() in a similar fashion.

— Reply to this email directly or view it on GitHub https://github.com/qos-ch/slf4j/pull/115#issuecomment-171006529.

[adorokhine]

LazyStackTrace is implemented by obtaining a reference to some sun internal classes via reflection. If those classes are not available, it falls back to Thread.getStackTrace().

The code is here: https://github.com/google/guava/blob/master/guava/src/com/google/common/base/Throwables.java (getJLA())

Also that method was only implemented in JDK7, so in non-sun JDKs, and in sun JDKs <=6, it still falls back to the normal method of getting a throwable.

Should I go ahead and implement this? Any concerns?

On 12 January 2016 at 10:50, Alexander Dorokhine [email protected] wrote:

Thanks Matt for the interesting pointer! I will take a look at LazyStackTrace this week.

On 12 January 2016 at 10:40, Matt Bishop [email protected] wrote:

To clarify, I am not suggesting we use Guava here, but instead look at how they implemented it and see if you can implement Logger.getLogger() in a similar fashion.

— Reply to this email directly or view it on GitHub https://github.com/qos-ch/slf4j/pull/115#issuecomment-171006529.

[mattbishop]

@adorokhine yes I would be interested to see what you come up with. Many use Java 7 and higher now so it would be useful for them to have a performant way to call getLogger(). Naturally we cannot break compatibility with Java6 yet.

[adorokhine]

@mattbishop While implementing this, I discovered that there is a security manager setting called "accessClassInPackage.sun.misc" which disables any access to sun.misc.. With this setting enabled, Class.forName("sun.misc.") does not work.

Caused by: java.security.AccessControlException: access denied ("java.lang.RuntimePermission" "accessClassInPackage.sun.misc")
    at java.security.AccessControlContext.checkPermission(AccessControlContext.java:474)
    at java.security.AccessController.checkPermission(AccessController.java:685)
    at java.lang.SecurityManager.checkPermission(SecurityManager.java:549)
    at java.lang.SecurityManager.checkPackageAccess(SecurityManager.java:1525)
    at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:305)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:358)
    at java.lang.Class.forName0(Native Method)
    at java.lang.Class.forName(Class.java:195)
    at org.slf4j.helpers.callingclass.LazyExceptionCallingClassFinder.createInstance(LazyExceptionCallingClassFinder.java:84)
    at org.slf4j.helpers.Util.createCallingClassFinder(Util.java:63)
    at org.slf4j.helpers.Util.<clinit>(Util.java:43)
    ... 17 more

Any thoughts? Are we ok with this limitation?