Re: QA Test debugging

[Peter Firmstone]

Bryan,

I'm interrogating the usual suspects first.
I've checked com.sun.jini.start.AggregatePolicyProvider and 
MergedPolicyProvider but they look clean, java.security.Permissions is 
known to have UnresolvablePermissions and not resolve them, however that 
visibility issue is limited to UnresolvePermission's (I had to write an 
entire replacement in 
org.apache.river.api.security.ConcurrentPermissions to get around that 
issue, that's another story, I haven't raised a bug with Oracle, I'll do 
that after they sort out the SocketPermission concurrency bug I've 
raised, don't want to give them too much work all at once :).

From java.security.Permission javadoc:

Permission objects are similar to String objects in that they are 
immutable once they have been created. Subclasses should not provide 
methods that can change the state of a permission once it has been 
created. 

SocketPermission, breaks this contract, it mutates internally after 
construction, this might be affecting thread visibility.

I noticed test failures aren't definite, the number of failed tests has 
been reduced significantly by enabling security debugging, luckily we're 
still seeing failures however.

We're going to need to step through one of these tests and cofirm the 
policy provider and check SocketPermission.implies().

I suspect we're having issues with SocketPermission's thread visibility.

If that's the case, there are three options for a fix:

  1. Wait for Oracle to fix it (don't get your hopes up).
  2. Construct SocketPermission on demand and thread confine it.
  3. Create a replacement for SocketPermission and
     SocketPermissionCollection and substitute.

If the issue is SocketPermission, I'll probably go for option 2.

If it's something else, or the problem goes away during debugging, it 
could require much head scratching to fix (brute force patch attempts).

The major problem is SocketPermission isn't being implied, the 
ProtectionDomain clearly has the required Permission, see appended.

I'll get back to you with a patch to enable debugging and some instructions.

Thanks again for helping,

Peter.

ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:access: access denied 
(java.net.SocketPermission bryan-thompson-macbook-Air.local 
connect,accept,resolve)
      [java] ActSys-err: Feb 24, 2013 8:24:07 
AM:Group-0:err:java.lang.Exception: Stack trace
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.lang.Thread.dumpStack(Thread.java:1273)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.security.AccessControlContext.checkPermission(AccessControlContext.java:364)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.security.AccessController.checkPermission(AccessController.java:549)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.lang.SecurityManager.checkPermission(SecurityManager.java:532)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.net.URLClassLoader$4.run(URLClassLoader.java:515)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.security.AccessController.doPrivileged(Native Method)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.net.URLClassLoader.getPermissions(URLClassLoader.java:513)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
net.jini.loader.pref.PreferredClassLoader.getPermissions(PreferredClassLoader.java:1137)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.security.SecureClassLoader.getProtectionDomain(SecureClassLoader.java:235)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.security.SecureClassLoader.defineClass(SecureClassLoader.java:141)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.net.URLClassLoader.defineClass(URLClassLoader.java:283)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.net.URLClassLoader.access$000(URLClassLoader.java:58)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.net.URLClassLoader$1.run(URLClassLoader.java:197)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.security.AccessController.doPrivileged(Native Method)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.net.URLClassLoader.findClass(URLClassLoader.java:190)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.lang.ClassLoader.loadClass(ClassLoader.java:306)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
net.jini.loader.pref.PreferredClassLoader.loadClass(PreferredClassLoader.java:965)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.lang.ClassLoader.loadClass(ClassLoader.java:247)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.lang.Class.getDeclaredMethods0(Native Method)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.lang.Class.privateGetDeclaredMethods(Class.java:2436)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.lang.Class.privateGetPublicMethods(Class.java:2556)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.lang.Class.getMethods(Class.java:1412)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
sun.misc.ProxyGenerator.generateClassFile(ProxyGenerator.java:409)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
sun.misc.ProxyGenerator.generateProxyClass(ProxyGenerator.java:306)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.lang.reflect.Proxy.getProxyClass0(Proxy.java:610)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.lang.reflect.Proxy.getProxyClass(Proxy.java:394)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
net.jini.loader.pref.PreferredClassProvider.loadProxyClass(PreferredClassProvider.java:1308)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
net.jini.loader.pref.PreferredClassProvider.loadProxyClass(PreferredClassProvider.java:1186)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.rmi.server.RMIClassLoader.loadProxyClass(RMIClassLoader.java:294)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
net.jini.loader.ClassLoading.loadProxyClass(ClassLoading.java:240)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
net.jini.io.MarshalInputStream.resolveProxyClass(MarshalInputStream.java:373)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.io.ObjectInputStream.readProxyDesc(ObjectInputStream.java:1528)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.io.ObjectInputStream.readClassDesc(ObjectInputStream.java:1490)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1729)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1326)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.io.ObjectInputStream.defaultReadFields(ObjectInputStream.java:1950)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1874)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1756)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1326)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.io.ObjectInputStream.readObject(ObjectInputStream.java:348)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
com.sun.jini.jeri.internal.runtime.Util.unmarshalValue(Util.java:221)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
net.jini.jeri.BasicInvocationDispatcher.unmarshalArguments(BasicInvocationDispatcher.java:1057)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
net.jini.jeri.BasicInvocationDispatcher.dispatch(BasicInvocationDispatcher.java:601)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
com.sun.jini.jeri.internal.runtime.Target$2.run(Target.java:491)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
net.jini.export.ServerContext.doWithServerContext(ServerContext.java:108)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
com.sun.jini.jeri.internal.runtime.Target.dispatch(Target.java:488)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
com.sun.jini.jeri.internal.runtime.Target.access$000(Target.java:57)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
com.sun.jini.jeri.internal.runtime.Target$1.run(Target.java:464)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.security.AccessController.doPrivileged(Native Method)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
com.sun.jini.jeri.internal.runtime.Target.dispatch(Target.java:461)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
com.sun.jini.jeri.internal.runtime.Target.dispatch(Target.java:426)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
com.sun.jini.jeri.internal.runtime.DgcRequestDispatcher.dispatch(DgcRequestDispatcher.java:210)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
net.jini.jeri.connection.ServerConnectionManager$Dispatcher.dispatch(ServerConnectionManager.java:147)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
com.sun.jini.jeri.internal.mux.MuxServer$1$1.run(MuxServer.java:244)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.security.AccessController.doPrivileged(Native Method)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
com.sun.jini.jeri.internal.mux.MuxServer$1.run(MuxServer.java:241)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
com.sun.jini.thread.ThreadPool$Task.run(ThreadPool.java:143)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
com.sun.jini.thread.ThreadPool$Worker.run(ThreadPool.java:177)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:   at 
java.lang.Thread.run(Thread.java:680)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:access: access 
allowed (java.security.SecurityPermission getPolicy)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:access: domain that 
failed ProtectionDomain  
(http://bryan-thompson-macbook-Air.local:9080/phoenix-dl.jar<no signer 
certificates>)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: null
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err:<no principals>
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
java.security.Permissions@ec0a9f9 (
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.io.FilePermission /Users/bryan/Documents/workspace/river/trunk/qa/lib/- 
read)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.util.PropertyPermission apple.laf.* read,write)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.util.PropertyPermission java.vm.version read)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.util.PropertyPermission java.vendor.url read)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.util.PropertyPermission java.vm.name read)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.util.PropertyPermission com.apple.macos.useScreenMenuBar read,write)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.util.PropertyPermission java.version read)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.util.PropertyPermission file.separator read)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.util.PropertyPermission java.specification.vendor read)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.util.PropertyPermission line.separator read)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.util.PropertyPermission java.vm.specification.version read)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.util.PropertyPermission FILEPOLICY02 read)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.util.PropertyPermission java.vm.specification.vendor read)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.util.PropertyPermission java.* read)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.util.PropertyPermission os.name read)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.util.PropertyPermission java.system.class.loader read)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.util.PropertyPermission java.vm.vendor read)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.util.PropertyPermission path.separator read)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.util.PropertyPermission java.specification.name read)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.util.PropertyPermission os.version read)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.util.PropertyPermission com.sun.jini.reggie.enableImplToStubReplacement 
read)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.util.PropertyPermission com.apple.hwaccel read,write)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.util.PropertyPermission mrj.version read)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.util.PropertyPermission os.arch read)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.util.PropertyPermission apple.awt.* read,write)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.util.PropertyPermission java.class.version read)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.util.PropertyPermission java.vendor read)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.util.PropertyPermission java.vm.specification.name read)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.util.PropertyPermission java.specification.version read)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: (unresolved 
com.sun.jini.phoenix.ExecPermission /bin/javax )
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: (unresolved 
com.sun.jini.phoenix.ExecPermission /bin/javax )
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: (unresolved 
com.sun.jini.phoenix.ExecOptionPermission * )
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: (unresolved 
com.sun.jini.phoenix.ExecOptionPermission * )
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.security.SecurityPermission getPolicy)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.lang.RuntimePermission createClassLoader)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.lang.RuntimePermission stopThread)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.net.SocketPermission bryan-thompson-macbook-Air.local 
connect,accept,resolve)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.net.SocketPermission bryan-thompson-macbook-Air.local:9080 
connect,resolve)
      [java] ActSys-err: Feb 24, 2013 8:24:07 AM:Group-0:err: 
(java.net.SocketPermission localhost:1024- listen,resolve)