You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@river.apache.org by Peter Firmstone <pe...@zeus.net.au> on 2013/04/18 13:27:49 UTC

Transaction Test failure example

This test appears to fail due to asynchronicity

The abort task is submitted to the TaskManager before the test thread 
sleeps for 1 second, but the abort task attempts to execute after the 
test completes.

Is it reasonable to expect that a transaction must abort before 1 second 
elapses?

This task always returns false for runAfter, so shouldn't be affected by 
the TaskManager issue.

I suspect the delay occurs because the TaskManager and WakeupManager 
don't have any running threads at the time the abort task is submitted.

In a network environment, I'd be satisfied if the transaction aborts 
eventually, is it possible to make a time guarantee in a network 
environment?

Regards,

Peter.

Running 
com/sun/jini/test/impl/outrigger/leasing/UseTxnMgrSpaceLeaseTestRenewCancel.td
Time is Thu Apr 18 21:12:34 EST 2013
Starting test in separate process with command:
'C:\Program Files\Java\jdk1.6.0_26\jre\bin\java' 
-Djava.security.manager=org.apache.river.api.security.CombinerSecurityManager 
-Djava.security.policy=file:/C:/Users/peter/Documents/NetBeansProjects/peterConcurrentPolicy/qa/harness/policy/defaulttest.policy 
'-Djava.rmi.server.codebase=http://medusa:9082/qa1-outrigger-dl.jar 
http://medusa:9082/qa1-share-dl.jar' -cp 
C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\jiniharness.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\jinitests.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\jsk-platform.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\jsk-lib.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\high-scale-lib.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\custard-apple-1.0.2.jar 
-ea -esa -client '-Djava.ext.dirs=C:\Program 
Files\Java\jdk1.6.0_26\jre\lib\ext;C:\windows\Sun\Java\lib\ext;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib-ext;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib-ext' 
-Dcom.sun.jini.jsk.port=9080 -Dcom.sun.jini.qa.port=9081 
-Dcom.sun.jini.jsk.home=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy 
-Dcom.sun.jini.qa.home=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa 
-Dcom.sun.jini.qa.harness.harnessJar=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\jiniharness.jar 
-Dcom.sun.jini.qa.harness.testJar=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\jinitests.jar 
-Dcom.sun.jini.qa.harness.runjiniserver=true 
-Dcom.sun.jini.qa.harness.runkitserver=true 
-Djava.security.properties=file:/C:/Users/peter/Documents/NetBeansProjects/peterConcurrentPolicy/qa/harness/trust/dynamic-policy.properties 
-Dcom.sun.jini.qa.harness.testhosts= 
-Djava.util.logging.config.file=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\src\com\sun\jini\test\resources\qa1.logging 
-Dcom.sun.jini.test.home=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa 
-Dcom.sun.jini.test.port=9082 
-Dcom.sun.jini.qa.harness.policies=file:/C:/Users/peter/Documents/NetBeansProjects/peterConcurrentPolicy/qa/src/com/sun/jini/test/resources/jinitest.policy 
'-Djava.ext.dirs=C:\Program 
Files\Java\jdk1.6.0_26\jre\lib\ext;C:\windows\Sun\Java\lib\ext;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib-ext;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib-ext' 
com.sun.jini.qa.harness.MasterTest 
com/sun/jini/test/impl/outrigger/leasing/UseTxnMgrSpaceLeaseTestRenewCancel.td 


TIME: 9:12:35 PM

QAConfig.loadTestConfiguration FINER: Test Configuration options:
QAConfig.loadTestConfiguration FINER:    -
QAConfig.loadTestConfiguration FINER:    multicast.ttl = 0
MasterTest.doTest INFO:
============================== CALLING CONSTRUCT() 
==============================

AdminManager.startService FINE: starting qaClassServer
AdminManager.getAdmin FINEST: getAdmin called with prefix qaClassServer
FINE:
FINE: Parameters for qaClassServer(.0):
FINE:      type              : classServer
FINE:      impl              : com.sun.jini.tool.ClassServer
FINE:      directory         : 
C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib
FINE:      options           : -ea -esa
AdminManager.startService FINE: starting jiniClassServer
AdminManager.getAdmin FINEST: getAdmin called with prefix jiniClassServer
18/04/2013 9:12:35 PM com.sun.jini.tool.ClassServer run
INFO: ClassServer started 
[[C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\], 
port 9081]
FINE:
FINE: Parameters for jiniClassServer(.0):
FINE:      type              : classServer
FINE:      impl              : com.sun.jini.tool.ClassServer
FINE:      directory         : 
C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib-dl
FINE:      options           : -ea -esa
AdminManager.startService FINE: starting testClassServer
AdminManager.getAdmin FINEST: getAdmin called with prefix testClassServer
FINE:
FINE: Parameters for testClassServer(.0):
FINE:      type              : classServer
FINE:      impl              : com.sun.jini.tool.ClassServer
FINE:      directory         : 
C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib
FINE:      options           : -ea -esa
TestBase.construct FINE: Test Name = 
com.sun.jini.test.impl.outrigger.leasing.UseTxnMgrSpaceLeaseTest
LeaseGrantTestBase.parse INFO: exact = true
LeaseGrantTestBase.parse INFO: clip = -1
LeaseGrantTestBase.parse INFO: slop = 3,000
LeaseGrantTestBase.parse INFO: durationRequest = 60,000
LeaseUsesTestBase.parse INFO: renewals = 2
LeaseUsesTestBase.parse INFO: cancel = true
LeaseUsesTestBase.parse INFO: renewWait = -1
LeaseUsesTestBase.parse INFO: shutdownTime = -1
LeaseUsesTestBase.parse INFO: restartSleep = 10,000
LeaseUsesTestBase.parse INFO: cancelSlop = 1,000
LeaseGrantTestBase.parse INFO: exact = true
LeaseGrantTestBase.parse INFO: clip = -1
LeaseGrantTestBase.parse INFO: slop = 3,000
LeaseGrantTestBase.parse INFO: durationRequest = 60,000
LeaseUsesTestBase.parse INFO: renewals = 2
LeaseUsesTestBase.parse INFO: cancel = true
LeaseUsesTestBase.parse INFO: renewWait = -1
LeaseUsesTestBase.parse INFO: shutdownTime = -1
LeaseUsesTestBase.parse INFO: restartSleep = 10,000
LeaseUsesTestBase.parse INFO: cancelSlop = 1,000
MasterTest.doTest INFO:
=============================== CALLING RUN() 
===============================

18/04/2013 9:12:35 PM com.sun.jini.tool.ClassServer run
INFO: ClassServer started 
[[C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib-dl\], 
port 9080]
18/04/2013 9:12:35 PM com.sun.jini.tool.ClassServer run
INFO: ClassServer started 
[[C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\], 
port 9082]
TestBase.dbgSpecSrvcs FINE: 
TestBase.specifyServices({net.jini.core.transaction.server.TransactionManager,net.jini.space.JavaSpace})
TestBase.dbgSpecSrvcs FINE: specifyServices groups=null locator=null 
useLookup =true
AdminManager.startService FINE: starting 
net.jini.core.lookup.ServiceRegistrar
AdminManager.getAdmin FINEST: getAdmin called with prefix 
net.jini.core.lookup.ServiceRegistrar
QAConfig.getServiceHost FINE: Selecting service host
QAConfig.getServiceHost FINE: Not distributed - selecting this host
AbstractServiceAdmin.addServiceExporter FINER: no exporter definition 
provided
NonActivatableServiceStarterAdmin.getGroup FINER: Creating shared group
AdminManager.startService FINE: starting nonActivatableGroup
AdminManager.getAdmin FINEST: getAdmin called with prefix 
nonActivatableGroup
NonActivatableGroupAdmin.start FINER: NonActivatableGroup exec command 
line: 'C:\Program Files\Java\jdk1.6.0_26\jre/bin/java 
-Djava.rmi.server.codebase=http://medusa:9081/nonactivatablegroup-dl.jar 
-Djava.security.policy=file:/C:/Users/peter/Documents/NetBeansProjects/peterConcurrentPolicy/qa/harness/policy/defaultnonactvm.policy 
-ea -esa -server -Djava.ext.dirs=C:\Program 
Files\Java\jdk1.6.0_26\jre\lib\ext;C:\windows\Sun\Java\lib\ext;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib-ext;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib-ext 
-Dcom.sun.jini.jsk.port=9080 -Dcom.sun.jini.qa.port=9081 
-Dcom.sun.jini.jsk.home=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy 
-Dcom.sun.jini.qa.home=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa 
-Dcom.sun.jini.qa.harness.harnessJar=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\jiniharness.jar 
-Dcom.sun.jini.qa.harness.testJar=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\jinitests.jar 
-Dcom.sun.jini.qa.harness.runjiniserver=true 
-Dcom.sun.jini.qa.harness.runkitserver=true 
-Djava.security.properties=file:/C:/Users/peter/Documents/NetBeansProjects/peterConcurrentPolicy/qa/harness/trust/dynamic-policy.properties 
-Dcom.sun.jini.qa.harness.testhosts= 
-Djava.util.logging.config.file=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\src\com\sun\jini\test\resources\qa1.logging 
-Dcom.sun.jini.test.home=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa 
-Dcom.sun.jini.test.port=9082 
-Dcom.sun.jini.qa.harness.policies=file:/C:/Users/peter/Documents/NetBeansProjects/peterConcurrentPolicy/qa/src/com/sun/jini/test/resources/jinitest.policy 
-cp 
C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\nonactivatablegroup.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\start.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\jsk-platform.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\custard-apple-1.0.2.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\high-scale-lib.jar 
com.sun.jini.qa.harness.NonActivatableGroupImpl'
FINE:
FINE: Parameters for nonActivatableGroup(.0):
FINE:      type              : nonactivatablegroup
FINE:      codebase          : http://medusa:9081/nonactivatablegroup-dl.jar
FINE:      impl              : 
com.sun.jini.qa.harness.NonActivatableGroupImpl
FINE:      policy file       : 
file:/C:/Users/peter/Documents/NetBeansProjects/peterConcurrentPolicy/qa/harness/policy/defaultnonactvm.policy
FINE:      classpath         : 
C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\nonactivatablegroup.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\start.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\jsk-platform.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\custard-apple-1.0.2.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\high-scale-lib.jar
FINE:      options           : -ea -esa -server
FINE:      properties        : -Djava.ext.dirs=C:\Program 
Files\Java\jdk1.6.0_26\jre\lib\ext;C:\windows\Sun\Java\lib\ext;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib-ext;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib-ext
FINE:                        : -Dcom.sun.jini.jsk.port=9080
FINE:                        : -Dcom.sun.jini.qa.port=9081
FINE:                        : 
-Dcom.sun.jini.jsk.home=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy
FINE:                        : 
-Dcom.sun.jini.qa.home=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa
FINE:                        : 
-Dcom.sun.jini.qa.harness.harnessJar=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\jiniharness.jar
FINE:                        : 
-Dcom.sun.jini.qa.harness.testJar=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\jinitests.jar
FINE:                        : -Dcom.sun.jini.qa.harness.runjiniserver=true
FINE:                        : -Dcom.sun.jini.qa.harness.runkitserver=true
FINE:                        : 
-Djava.security.properties=file:/C:/Users/peter/Documents/NetBeansProjects/peterConcurrentPolicy/qa/harness/trust/dynamic-policy.properties
FINE:                        : -Dcom.sun.jini.qa.harness.testhosts=
FINE:                        : 
-Djava.util.logging.config.file=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\src\com\sun\jini\test\resources\qa1.logging
FINE:                        : 
-Dcom.sun.jini.test.home=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa
FINE:                        : -Dcom.sun.jini.test.port=9082
FINE:                        : 
-Dcom.sun.jini.qa.harness.policies=file:/C:/Users/peter/Documents/NetBeansProjects/peterConcurrentPolicy/qa/src/com/sun/jini/test/resources/jinitest.policy
FINE:
FINE: Parameters for net.jini.core.lookup.ServiceRegistrar(.0):
FINE:      type              : transient
FINE:      codebase          : http://medusa:9080/reggie-dl.jar 
http://medusa:9080/jsk-dl.jar
FINE:      impl              : com.sun.jini.reggie.TransientRegistrarImpl
FINE:      component name    : com.sun.jini.reggie
FINE:      policy file       : 
file:/C:/Users/peter/Documents/NetBeansProjects/peterConcurrentPolicy/qa/harness/policy/defaultreggie.policy
FINE:      classpath         : 
C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\reggie.jar
FINE:      service conf file : -
FINE:      starter conf file : -
FINE:      proxy preparer    : test.reggiePreparer
FINE:      option args 0     : -
FINE:      option args 1     : com.sun.jini.reggie.initialMemberGroups = 
new String[]{"QATestDefaultGroup_medusa_1366283554592"}
FINE:      option args 2     : multicast.ttl=0
FINE:
TestBase.specifyServices FINE: Starting service #0: 
net.jini.core.transaction.server.TransactionManager
AdminManager.startService FINE: starting 
net.jini.core.transaction.server.TransactionManager
AdminManager.getAdmin FINEST: getAdmin called with prefix 
net.jini.core.transaction.server.TransactionManager
QAConfig.getServiceHost FINE: Selecting service host
QAConfig.getServiceHost FINE: Not distributed - selecting this host
AbstractServiceAdmin.addServiceExporter FINER: no exporter definition 
provided
FINE:
FINE: Parameters for 
net.jini.core.transaction.server.TransactionManager(.0):
FINE:      type              : transient
FINE:      codebase          : http://medusa:9080/mahalo-dl.jar 
http://medusa:9080/jsk-dl.jar
FINE:      impl              : com.sun.jini.mahalo.TransientMahaloImpl
FINE:      component name    : com.sun.jini.mahalo
FINE:      policy file       : 
file:/C:/Users/peter/Documents/NetBeansProjects/peterConcurrentPolicy/qa/harness/policy/defaultmahalo.policy
FINE:      classpath         : 
C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\mahalo.jar
FINE:      service conf file : -
FINE:      starter conf file : -
FINE:      proxy preparer    : test.mahaloPreparer
FINE:      option args 0     : -
FINE:      option args 1     : com.sun.jini.mahalo.initialLookupGroups = 
new String[]{"QATestDefaultGroup_medusa_1366283554592"}
FINE:      option args 2     : com.sun.jini.mahalo.persistenceDirectory 
= 
"C:\\Users\\peter\\AppData\\Local\\Temp\\TxnManagerImpl_log0620075686508648010dir"
FINE:      option args 3     : multicast.ttl=0
FINE:
TestBase.specifyServices FINE: Starting service #1: net.jini.space.JavaSpace
AdminManager.startService FINE: starting net.jini.space.JavaSpace
AdminManager.getAdmin FINEST: getAdmin called with prefix 
net.jini.space.JavaSpace
QAConfig.getServiceHost FINE: Selecting service host
QAConfig.getServiceHost FINE: Not distributed - selecting this host
AbstractServiceAdmin.addServiceExporter FINER: no exporter definition 
provided
FINE:
FINE: Parameters for net.jini.space.JavaSpace(.0):
FINE:      type              : transient
FINE:      codebase          : http://medusa:9080/outrigger-dl.jar 
http://medusa:9080/jsk-dl.jar
FINE:      impl              : com.sun.jini.outrigger.TransientOutriggerImpl
FINE:      component name    : com.sun.jini.outrigger
FINE:      policy file       : 
file:/C:/Users/peter/Documents/NetBeansProjects/peterConcurrentPolicy/qa/harness/policy/defaultoutrigger.policy
FINE:      classpath         : 
C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\outrigger.jar
FINE:      service conf file : -
FINE:      starter conf file : -
FINE:      proxy preparer    : test.outriggerPreparer
FINE:      option args 0     : -
FINE:      option args 1     : 
com.sun.jini.outrigger.initialLookupGroups = new 
String[]{"QATestDefaultGroup_medusa_1366283554592"}
FINE:      option args 2     : 
com.sun.jini.outrigger.persistenceDirectory = 
"C:\\Users\\peter\\AppData\\Local\\Temp\\FrontEndSpace_log1541272959550710117dir"
FINE:      option args 3     : com.sun.jini.outrigger.store=new 
com.sun.jini.outrigger.snaplogstore.LogStore(this)
FINE:      option args 4     : multicast.ttl=0
FINE:
LeaseUsesTestBase.run INFO: Resource acquired
LeaseGrantTestBase.logRequest INFO: Lease resource: 
LandlordLease:b4bb0af8-d728-8ea9-96a5-5571da8dc7ce 
landlord:Proxy[TxnManager,BasicInvocationHandler[BasicObjectEndpoint[e33c6831-5a58-4df1-a277-d0795d8e7b68,TcpEndpoint[10.22.97.167:57567]]]] 
landlordUuid:cf2087ae-5a97-41f9-b4bb-0af8d7288ea9 
com.sun.jini.landlord.ConstrainableLandlordLease@2fbb16ee
LeaseGrantTestBase.logRequest INFO:     req:1,366,283,620,704
LeaseGrantTestBase.logRequest INFO:     got:1,366,283,620,686
LeaseGrantTestBase.logRequest INFO:     aprox duration:59,982
LeaseGrantTestBase.logRequest INFO:     drift:-18
LeaseUsesTestBase.run INFO: Expire Test: Slop = 3,000
LeaseUsesTestBase.run FINEST: postTime: 1,366,283,560,855, (expTime - 
slop): 1,366,283,617,686
LeaseUsesTestBase.run FINEST: postTime: 1,366,283,560,886, (expTime - 
slop): 1,366,283,617,686

<SNIP>

LeaseUsesTestBase.run FINEST: postTime: 1,366,283,620,713, (expTime - 
slop): 1,366,283,647,706
LeaseGrantTestBase.logRequest INFO: Lease renew: 
LandlordLease:b4bb0af8-d728-8ea9-96a5-5571da8dc7ce 
landlord:Proxy[TxnManager,BasicInvocationHandler[BasicObjectEndpoint[e33c6831-5a58-4df1-a277-d0795d8e7b68,TcpEndpoint[10.22.97.167:57567]]]] 
landlordUuid:cf2087ae-5a97-41f9-b4bb-0af8d7288ea9 
com.sun.jini.landlord.ConstrainableLandlordLease@2fbb16ee
LeaseGrantTestBase.logRequest INFO:     req:1,366,283,680,723
LeaseGrantTestBase.logRequest INFO:     got:1,366,283,680,723
LeaseGrantTestBase.logRequest INFO:     aprox duration:60,000
LeaseGrantTestBase.logRequest INFO:     drift:0
LeaseUsesTestBase.run FINEST: postTime: 1,366,283,620,739, (expTime - 
slop): 1,366,283,677,723
LeaseUsesTestBase.cancel INFO: Cancel Test: checking for availability
LeaseUsesTestBase.cancel INFO: Cancel Test: canceling lease
NonActGrp-out: net.jini.core.transaction.TimeoutExpiredException: 
timeout expired
NonActGrp-out:     at 
com.sun.jini.mahalo.TxnManagerTransaction.abort(TxnManagerTransaction.java:1033)
NonActGrp-out:     at 
com.sun.jini.mahalo.TxnManagerImpl.abort(TxnManagerImpl.java:795)
NonActGrp-out:     at 
com.sun.jini.mahalo.TxnManagerImpl.abort(TxnManagerImpl.java:741)
NonActGrp-out:     at 
com.sun.jini.mahalo.TxnManagerImpl.cancel(TxnManagerImpl.java:1047)
NonActGrp-out:     at 
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
NonActGrp-out:     at 
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
NonActGrp-out:     at 
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
NonActGrp-out:     at java.lang.reflect.Method.invoke(Method.java:597)
NonActGrp-out:     at 
net.jini.jeri.BasicInvocationDispatcher.invoke(BasicInvocationDispatcher.java:1134)
NonActGrp-out:     at 
net.jini.jeri.BasicInvocationDispatcher.dispatch(BasicInvocationDispatcher.java:610)
NonActGrp-out:     at 
com.sun.jini.jeri.internal.runtime.Target$2.run(Target.java:491)
NonActGrp-out:     at 
net.jini.export.ServerContext.doWithServerContext(ServerContext.java:108)
NonActGrp-out:     at 
com.sun.jini.jeri.internal.runtime.Target.dispatch(Target.java:488)
NonActGrp-out:     at 
com.sun.jini.jeri.internal.runtime.Target.access$000(Target.java:57)
NonActGrp-out:     at 
com.sun.jini.jeri.internal.runtime.Target$1.run(Target.java:464)
NonActGrp-out:     at 
com.sun.jini.start.AggregatePolicyProvider$AggregateSecurityContext$2.run(AggregatePolicyProvider.java:593)
NonActGrp-out:     at java.security.AccessController.doPrivileged(Native 
Method)
NonActGrp-out:     at 
com.sun.jini.jeri.internal.runtime.Target.dispatch(Target.java:461)
NonActGrp-out:     at 
com.sun.jini.jeri.internal.runtime.Target.dispatch(Target.java:426)
NonActGrp-out:     at 
com.sun.jini.jeri.internal.runtime.DgcRequestDispatcher.dispatch(DgcRequestDispatcher.java:210)
NonActGrp-out:     at 
net.jini.jeri.connection.ServerConnectionManager$Dispatcher.dispatch(ServerConnectionManager.java:147)
NonActGrp-out:     at 
com.sun.jini.jeri.internal.mux.MuxServer$1$1.run(MuxServer.java:244)
NonActGrp-out:     at 
com.sun.jini.start.AggregatePolicyProvider$AggregateSecurityContext$1.run(AggregatePolicyProvider.java:579)
NonActGrp-out:     at java.security.AccessController.doPrivileged(Native 
Method)
NonActGrp-out:     at 
com.sun.jini.jeri.internal.mux.MuxServer$1.run(MuxServer.java:241)
NonActGrp-out:     at 
com.sun.jini.thread.ThreadPool$Task.run(ThreadPool.java:143)
NonActGrp-out:     at 
com.sun.jini.thread.ThreadPool$Worker.run(ThreadPool.java:187)
NonActGrp-out:     at java.lang.Thread.run(Thread.java:662)
LeaseUsesTestBase.cancel INFO: Sleeping for 1,000 milliseconds to allow 
cancel to propagate...
LeaseUsesTestBase.cancel INFO: awake
LeaseUsesTestBase.cancel INFO: Cancel Test: checking to make sure 
resource is gone
com.sun.jini.qa.harness.TestException: Resource was available after cancel
     at 
com.sun.jini.test.impl.outrigger.leasing.LeaseUsesTestBase.cancel(LeaseUsesTestBase.java:289)
     at 
com.sun.jini.test.impl.outrigger.leasing.LeaseUsesTestBase.run(LeaseUsesTestBase.java:242)
     at com.sun.jini.qa.harness.MasterTest.doTest(MasterTest.java:256)
     at com.sun.jini.qa.harness.MasterTest.main(MasterTest.java:144)
MasterTest.doTest INFO:
============================ CALLING TEARDOWN() 
=============================


TIME: 9:14:08 PM

TestBase.tearDown FINE: Waiting 0 ms after cleanup() call
QATestEnvironment.tearDown FINE: Destroying remaining managed services
AdminManager.destroyService FINE: destroying service: class 
com.sun.jini.outrigger.ConstrainableSpaceProxy2
AdminManager.destroyService FINE: destroying service: class 
com.sun.jini.mahalo.TxnMgrProxy$ConstrainableTxnMgrProxy
AdminManager.destroyService FINE: destroying service: class 
com.sun.jini.reggie.ConstrainableRegistrarProxy
AdminManager.destroyService FINE: destroying service: class 
com.sun.jini.qa.harness.NonActivatableGroupImpl$GroupImpl_Stub
NonActGrp-out: 18/04/2013 9:14:09 PM 
com.sun.jini.thread.TaskManager$TaskThread run
NonActGrp-out: WARNING: Task.run exception
NonActGrp-out: java.lang.IllegalStateException: trying to add task to 
stopped WakeupManager
NonActGrp-out:     at 
com.sun.jini.thread.WakeupManager.schedule(WakeupManager.java:431)
NonActGrp-out:     at 
com.sun.jini.thread.WakeupManager.schedule(WakeupManager.java:416)
NonActGrp-out:     at com.sun.jini.thread.RetryTask.run(RetryTask.java:153)
NonActGrp-out:     at 
com.sun.jini.thread.TaskManager$TaskThread.run(TaskManager.java:335)
AdminManager.destroyService FINE: destroying service: class 
com.sun.jini.tool.ClassServer
18/04/2013 9:14:10 PM com.sun.jini.tool.ClassServer terminate
INFO: ClassServer terminated [port 9081]
AdminManager.destroyService FINE: destroying service: class 
com.sun.jini.tool.ClassServer
18/04/2013 9:14:10 PM com.sun.jini.tool.ClassServer terminate
INFO: ClassServer terminated [port 9081]
18/04/2013 9:14:10 PM com.sun.jini.tool.ClassServer terminate
INFO: ClassServer terminated [port 9082]
AdminManager.destroyService FINE: destroying service: class 
com.sun.jini.tool.ClassServer
18/04/2013 9:14:10 PM com.sun.jini.tool.ClassServer terminate
INFO: ClassServer terminated [port 9082]
18/04/2013 9:14:10 PM com.sun.jini.tool.ClassServer terminate
INFO: ClassServer terminated [port 9080]

TIME: 9:14:10 PM

Test process was destroyed and returned code 1
com/sun/jini/test/impl/outrigger/leasing/UseTxnMgrSpaceLeaseTestRenewCancel.td
Test Failed: Test Failed: com.sun.jini.qa.harness.TestException: 
Resource was available after cancel


-----------------------------------------

SUMMARY =================================

com/sun/jini/test/impl/outrigger/leasing/UseTxnMgrSpaceLeaseTestRenewCancel.td
Test Failed: Test Failed: com.sun.jini.qa.harness.TestException: 
Resource was available after cancel

-----------------------------------------

# of tests started   = 1
# of tests completed = 1
# of tests passed    = 0
# of tests failed    = 1

-----------------------------------------

    Date finished:
       Thu Apr 18 21:14:15 EST 2013
    Time elapsed:
       101 seconds

Java Result: 1
qa.collect-result:
C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\build.xml:2105: 
The following error occurred while executing this line:
C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\build.xml:357: 
condition satisfied
BUILD FAILED (total time: 1 minute 43 seconds)

Re: Transaction Test failure example

Posted by Peter Firmstone <ji...@zeus.net.au>.
I wonder if a garbage collection might also cause some latency?



On 18/04/2013 9:27 PM, Peter Firmstone wrote:
> This test appears to fail due to asynchronicity
>
> The abort task is submitted to the TaskManager before the test thread 
> sleeps for 1 second, but the abort task attempts to execute after the 
> test completes.
>
> Is it reasonable to expect that a transaction must abort before 1 
> second elapses?
>
> This task always returns false for runAfter, so shouldn't be affected 
> by the TaskManager issue.
>
> I suspect the delay occurs because the TaskManager and WakeupManager 
> don't have any running threads at the time the abort task is submitted.
>
> In a network environment, I'd be satisfied if the transaction aborts 
> eventually, is it possible to make a time guarantee in a network 
> environment?
>
> Regards,
>
> Peter.
>
> Running 
> com/sun/jini/test/impl/outrigger/leasing/UseTxnMgrSpaceLeaseTestRenewCancel.td
> Time is Thu Apr 18 21:12:34 EST 2013
> Starting test in separate process with command:
> 'C:\Program Files\Java\jdk1.6.0_26\jre\bin\java' 
> -Djava.security.manager=org.apache.river.api.security.CombinerSecurityManager 
> -Djava.security.policy=file:/C:/Users/peter/Documents/NetBeansProjects/peterConcurrentPolicy/qa/harness/policy/defaulttest.policy 
> '-Djava.rmi.server.codebase=http://medusa:9082/qa1-outrigger-dl.jar 
> http://medusa:9082/qa1-share-dl.jar' -cp 
> C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\jiniharness.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\jinitests.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\jsk-platform.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\jsk-lib.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\high-scale-lib.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\custard-apple-1.0.2.jar 
> -ea -esa -client '-Djava.ext.dirs=C:\Program 
> Files\Java\jdk1.6.0_26\jre\lib\ext;C:\windows\Sun\Java\lib\ext;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib-ext;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib-ext' 
> -Dcom.sun.jini.jsk.port=9080 -Dcom.sun.jini.qa.port=9081 
> -Dcom.sun.jini.jsk.home=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy 
> -Dcom.sun.jini.qa.home=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa 
> -Dcom.sun.jini.qa.harness.harnessJar=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\jiniharness.jar 
> -Dcom.sun.jini.qa.harness.testJar=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\jinitests.jar 
> -Dcom.sun.jini.qa.harness.runjiniserver=true 
> -Dcom.sun.jini.qa.harness.runkitserver=true 
> -Djava.security.properties=file:/C:/Users/peter/Documents/NetBeansProjects/peterConcurrentPolicy/qa/harness/trust/dynamic-policy.properties 
> -Dcom.sun.jini.qa.harness.testhosts= 
> -Djava.util.logging.config.file=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\src\com\sun\jini\test\resources\qa1.logging 
> -Dcom.sun.jini.test.home=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa 
> -Dcom.sun.jini.test.port=9082 
> -Dcom.sun.jini.qa.harness.policies=file:/C:/Users/peter/Documents/NetBeansProjects/peterConcurrentPolicy/qa/src/com/sun/jini/test/resources/jinitest.policy 
> '-Djava.ext.dirs=C:\Program 
> Files\Java\jdk1.6.0_26\jre\lib\ext;C:\windows\Sun\Java\lib\ext;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib-ext;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib-ext' 
> com.sun.jini.qa.harness.MasterTest 
> com/sun/jini/test/impl/outrigger/leasing/UseTxnMgrSpaceLeaseTestRenewCancel.td 
>
>
> TIME: 9:12:35 PM
>
> QAConfig.loadTestConfiguration FINER: Test Configuration options:
> QAConfig.loadTestConfiguration FINER:    -
> QAConfig.loadTestConfiguration FINER:    multicast.ttl = 0
> MasterTest.doTest INFO:
> ============================== CALLING CONSTRUCT() 
> ==============================
>
> AdminManager.startService FINE: starting qaClassServer
> AdminManager.getAdmin FINEST: getAdmin called with prefix qaClassServer
> FINE:
> FINE: Parameters for qaClassServer(.0):
> FINE:      type              : classServer
> FINE:      impl              : com.sun.jini.tool.ClassServer
> FINE:      directory         : 
> C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib
> FINE:      options           : -ea -esa
> AdminManager.startService FINE: starting jiniClassServer
> AdminManager.getAdmin FINEST: getAdmin called with prefix jiniClassServer
> 18/04/2013 9:12:35 PM com.sun.jini.tool.ClassServer run
> INFO: ClassServer started 
> [[C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\], 
> port 9081]
> FINE:
> FINE: Parameters for jiniClassServer(.0):
> FINE:      type              : classServer
> FINE:      impl              : com.sun.jini.tool.ClassServer
> FINE:      directory         : 
> C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib-dl
> FINE:      options           : -ea -esa
> AdminManager.startService FINE: starting testClassServer
> AdminManager.getAdmin FINEST: getAdmin called with prefix testClassServer
> FINE:
> FINE: Parameters for testClassServer(.0):
> FINE:      type              : classServer
> FINE:      impl              : com.sun.jini.tool.ClassServer
> FINE:      directory         : 
> C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib
> FINE:      options           : -ea -esa
> TestBase.construct FINE: Test Name = 
> com.sun.jini.test.impl.outrigger.leasing.UseTxnMgrSpaceLeaseTest
> LeaseGrantTestBase.parse INFO: exact = true
> LeaseGrantTestBase.parse INFO: clip = -1
> LeaseGrantTestBase.parse INFO: slop = 3,000
> LeaseGrantTestBase.parse INFO: durationRequest = 60,000
> LeaseUsesTestBase.parse INFO: renewals = 2
> LeaseUsesTestBase.parse INFO: cancel = true
> LeaseUsesTestBase.parse INFO: renewWait = -1
> LeaseUsesTestBase.parse INFO: shutdownTime = -1
> LeaseUsesTestBase.parse INFO: restartSleep = 10,000
> LeaseUsesTestBase.parse INFO: cancelSlop = 1,000
> LeaseGrantTestBase.parse INFO: exact = true
> LeaseGrantTestBase.parse INFO: clip = -1
> LeaseGrantTestBase.parse INFO: slop = 3,000
> LeaseGrantTestBase.parse INFO: durationRequest = 60,000
> LeaseUsesTestBase.parse INFO: renewals = 2
> LeaseUsesTestBase.parse INFO: cancel = true
> LeaseUsesTestBase.parse INFO: renewWait = -1
> LeaseUsesTestBase.parse INFO: shutdownTime = -1
> LeaseUsesTestBase.parse INFO: restartSleep = 10,000
> LeaseUsesTestBase.parse INFO: cancelSlop = 1,000
> MasterTest.doTest INFO:
> =============================== CALLING RUN() 
> ===============================
>
> 18/04/2013 9:12:35 PM com.sun.jini.tool.ClassServer run
> INFO: ClassServer started 
> [[C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib-dl\], 
> port 9080]
> 18/04/2013 9:12:35 PM com.sun.jini.tool.ClassServer run
> INFO: ClassServer started 
> [[C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\], 
> port 9082]
> TestBase.dbgSpecSrvcs FINE: 
> TestBase.specifyServices({net.jini.core.transaction.server.TransactionManager,net.jini.space.JavaSpace})
> TestBase.dbgSpecSrvcs FINE: specifyServices groups=null locator=null 
> useLookup =true
> AdminManager.startService FINE: starting 
> net.jini.core.lookup.ServiceRegistrar
> AdminManager.getAdmin FINEST: getAdmin called with prefix 
> net.jini.core.lookup.ServiceRegistrar
> QAConfig.getServiceHost FINE: Selecting service host
> QAConfig.getServiceHost FINE: Not distributed - selecting this host
> AbstractServiceAdmin.addServiceExporter FINER: no exporter definition 
> provided
> NonActivatableServiceStarterAdmin.getGroup FINER: Creating shared group
> AdminManager.startService FINE: starting nonActivatableGroup
> AdminManager.getAdmin FINEST: getAdmin called with prefix 
> nonActivatableGroup
> NonActivatableGroupAdmin.start FINER: NonActivatableGroup exec command 
> line: 'C:\Program Files\Java\jdk1.6.0_26\jre/bin/java 
> -Djava.rmi.server.codebase=http://medusa:9081/nonactivatablegroup-dl.jar 
> -Djava.security.policy=file:/C:/Users/peter/Documents/NetBeansProjects/peterConcurrentPolicy/qa/harness/policy/defaultnonactvm.policy 
> -ea -esa -server -Djava.ext.dirs=C:\Program 
> Files\Java\jdk1.6.0_26\jre\lib\ext;C:\windows\Sun\Java\lib\ext;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib-ext;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib-ext 
> -Dcom.sun.jini.jsk.port=9080 -Dcom.sun.jini.qa.port=9081 
> -Dcom.sun.jini.jsk.home=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy 
> -Dcom.sun.jini.qa.home=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa 
> -Dcom.sun.jini.qa.harness.harnessJar=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\jiniharness.jar 
> -Dcom.sun.jini.qa.harness.testJar=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\jinitests.jar 
> -Dcom.sun.jini.qa.harness.runjiniserver=true 
> -Dcom.sun.jini.qa.harness.runkitserver=true 
> -Djava.security.properties=file:/C:/Users/peter/Documents/NetBeansProjects/peterConcurrentPolicy/qa/harness/trust/dynamic-policy.properties 
> -Dcom.sun.jini.qa.harness.testhosts= 
> -Djava.util.logging.config.file=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\src\com\sun\jini\test\resources\qa1.logging 
> -Dcom.sun.jini.test.home=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa 
> -Dcom.sun.jini.test.port=9082 
> -Dcom.sun.jini.qa.harness.policies=file:/C:/Users/peter/Documents/NetBeansProjects/peterConcurrentPolicy/qa/src/com/sun/jini/test/resources/jinitest.policy 
> -cp 
> C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\nonactivatablegroup.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\start.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\jsk-platform.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\custard-apple-1.0.2.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\high-scale-lib.jar 
> com.sun.jini.qa.harness.NonActivatableGroupImpl'
> FINE:
> FINE: Parameters for nonActivatableGroup(.0):
> FINE:      type              : nonactivatablegroup
> FINE:      codebase          : 
> http://medusa:9081/nonactivatablegroup-dl.jar
> FINE:      impl              : 
> com.sun.jini.qa.harness.NonActivatableGroupImpl
> FINE:      policy file       : 
> file:/C:/Users/peter/Documents/NetBeansProjects/peterConcurrentPolicy/qa/harness/policy/defaultnonactvm.policy
> FINE:      classpath         : 
> C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\nonactivatablegroup.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\start.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\jsk-platform.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\custard-apple-1.0.2.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\high-scale-lib.jar
> FINE:      options           : -ea -esa -server
> FINE:      properties        : -Djava.ext.dirs=C:\Program 
> Files\Java\jdk1.6.0_26\jre\lib\ext;C:\windows\Sun\Java\lib\ext;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib-ext;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib-ext
> FINE:                        : -Dcom.sun.jini.jsk.port=9080
> FINE:                        : -Dcom.sun.jini.qa.port=9081
> FINE:                        : 
> -Dcom.sun.jini.jsk.home=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy
> FINE:                        : 
> -Dcom.sun.jini.qa.home=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa
> FINE:                        : 
> -Dcom.sun.jini.qa.harness.harnessJar=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\jiniharness.jar
> FINE:                        : 
> -Dcom.sun.jini.qa.harness.testJar=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\jinitests.jar
> FINE:                        : 
> -Dcom.sun.jini.qa.harness.runjiniserver=true
> FINE:                        : 
> -Dcom.sun.jini.qa.harness.runkitserver=true
> FINE:                        : 
> -Djava.security.properties=file:/C:/Users/peter/Documents/NetBeansProjects/peterConcurrentPolicy/qa/harness/trust/dynamic-policy.properties
> FINE:                        : -Dcom.sun.jini.qa.harness.testhosts=
> FINE:                        : 
> -Djava.util.logging.config.file=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\src\com\sun\jini\test\resources\qa1.logging
> FINE:                        : 
> -Dcom.sun.jini.test.home=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa
> FINE:                        : -Dcom.sun.jini.test.port=9082
> FINE:                        : 
> -Dcom.sun.jini.qa.harness.policies=file:/C:/Users/peter/Documents/NetBeansProjects/peterConcurrentPolicy/qa/src/com/sun/jini/test/resources/jinitest.policy
> FINE:
> FINE: Parameters for net.jini.core.lookup.ServiceRegistrar(.0):
> FINE:      type              : transient
> FINE:      codebase          : http://medusa:9080/reggie-dl.jar 
> http://medusa:9080/jsk-dl.jar
> FINE:      impl              : com.sun.jini.reggie.TransientRegistrarImpl
> FINE:      component name    : com.sun.jini.reggie
> FINE:      policy file       : 
> file:/C:/Users/peter/Documents/NetBeansProjects/peterConcurrentPolicy/qa/harness/policy/defaultreggie.policy
> FINE:      classpath         : 
> C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\reggie.jar
> FINE:      service conf file : -
> FINE:      starter conf file : -
> FINE:      proxy preparer    : test.reggiePreparer
> FINE:      option args 0     : -
> FINE:      option args 1     : com.sun.jini.reggie.initialMemberGroups 
> = new String[]{"QATestDefaultGroup_medusa_1366283554592"}
> FINE:      option args 2     : multicast.ttl=0
> FINE:
> TestBase.specifyServices FINE: Starting service #0: 
> net.jini.core.transaction.server.TransactionManager
> AdminManager.startService FINE: starting 
> net.jini.core.transaction.server.TransactionManager
> AdminManager.getAdmin FINEST: getAdmin called with prefix 
> net.jini.core.transaction.server.TransactionManager
> QAConfig.getServiceHost FINE: Selecting service host
> QAConfig.getServiceHost FINE: Not distributed - selecting this host
> AbstractServiceAdmin.addServiceExporter FINER: no exporter definition 
> provided
> FINE:
> FINE: Parameters for 
> net.jini.core.transaction.server.TransactionManager(.0):
> FINE:      type              : transient
> FINE:      codebase          : http://medusa:9080/mahalo-dl.jar 
> http://medusa:9080/jsk-dl.jar
> FINE:      impl              : com.sun.jini.mahalo.TransientMahaloImpl
> FINE:      component name    : com.sun.jini.mahalo
> FINE:      policy file       : 
> file:/C:/Users/peter/Documents/NetBeansProjects/peterConcurrentPolicy/qa/harness/policy/defaultmahalo.policy
> FINE:      classpath         : 
> C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\mahalo.jar
> FINE:      service conf file : -
> FINE:      starter conf file : -
> FINE:      proxy preparer    : test.mahaloPreparer
> FINE:      option args 0     : -
> FINE:      option args 1     : com.sun.jini.mahalo.initialLookupGroups 
> = new String[]{"QATestDefaultGroup_medusa_1366283554592"}
> FINE:      option args 2     : 
> com.sun.jini.mahalo.persistenceDirectory = 
> "C:\\Users\\peter\\AppData\\Local\\Temp\\TxnManagerImpl_log0620075686508648010dir"
> FINE:      option args 3     : multicast.ttl=0
> FINE:
> TestBase.specifyServices FINE: Starting service #1: 
> net.jini.space.JavaSpace
> AdminManager.startService FINE: starting net.jini.space.JavaSpace
> AdminManager.getAdmin FINEST: getAdmin called with prefix 
> net.jini.space.JavaSpace
> QAConfig.getServiceHost FINE: Selecting service host
> QAConfig.getServiceHost FINE: Not distributed - selecting this host
> AbstractServiceAdmin.addServiceExporter FINER: no exporter definition 
> provided
> FINE:
> FINE: Parameters for net.jini.space.JavaSpace(.0):
> FINE:      type              : transient
> FINE:      codebase          : http://medusa:9080/outrigger-dl.jar 
> http://medusa:9080/jsk-dl.jar
> FINE:      impl              : 
> com.sun.jini.outrigger.TransientOutriggerImpl
> FINE:      component name    : com.sun.jini.outrigger
> FINE:      policy file       : 
> file:/C:/Users/peter/Documents/NetBeansProjects/peterConcurrentPolicy/qa/harness/policy/defaultoutrigger.policy
> FINE:      classpath         : 
> C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\outrigger.jar
> FINE:      service conf file : -
> FINE:      starter conf file : -
> FINE:      proxy preparer    : test.outriggerPreparer
> FINE:      option args 0     : -
> FINE:      option args 1     : 
> com.sun.jini.outrigger.initialLookupGroups = new 
> String[]{"QATestDefaultGroup_medusa_1366283554592"}
> FINE:      option args 2     : 
> com.sun.jini.outrigger.persistenceDirectory = 
> "C:\\Users\\peter\\AppData\\Local\\Temp\\FrontEndSpace_log1541272959550710117dir"
> FINE:      option args 3     : com.sun.jini.outrigger.store=new 
> com.sun.jini.outrigger.snaplogstore.LogStore(this)
> FINE:      option args 4     : multicast.ttl=0
> FINE:
> LeaseUsesTestBase.run INFO: Resource acquired
> LeaseGrantTestBase.logRequest INFO: Lease resource: 
> LandlordLease:b4bb0af8-d728-8ea9-96a5-5571da8dc7ce 
> landlord:Proxy[TxnManager,BasicInvocationHandler[BasicObjectEndpoint[e33c6831-5a58-4df1-a277-d0795d8e7b68,TcpEndpoint[10.22.97.167:57567]]]] 
> landlordUuid:cf2087ae-5a97-41f9-b4bb-0af8d7288ea9 
> com.sun.jini.landlord.ConstrainableLandlordLease@2fbb16ee
> LeaseGrantTestBase.logRequest INFO:     req:1,366,283,620,704
> LeaseGrantTestBase.logRequest INFO:     got:1,366,283,620,686
> LeaseGrantTestBase.logRequest INFO:     aprox duration:59,982
> LeaseGrantTestBase.logRequest INFO:     drift:-18
> LeaseUsesTestBase.run INFO: Expire Test: Slop = 3,000
> LeaseUsesTestBase.run FINEST: postTime: 1,366,283,560,855, (expTime - 
> slop): 1,366,283,617,686
> LeaseUsesTestBase.run FINEST: postTime: 1,366,283,560,886, (expTime - 
> slop): 1,366,283,617,686
>
> <SNIP>
>
> LeaseUsesTestBase.run FINEST: postTime: 1,366,283,620,713, (expTime - 
> slop): 1,366,283,647,706
> LeaseGrantTestBase.logRequest INFO: Lease renew: 
> LandlordLease:b4bb0af8-d728-8ea9-96a5-5571da8dc7ce 
> landlord:Proxy[TxnManager,BasicInvocationHandler[BasicObjectEndpoint[e33c6831-5a58-4df1-a277-d0795d8e7b68,TcpEndpoint[10.22.97.167:57567]]]] 
> landlordUuid:cf2087ae-5a97-41f9-b4bb-0af8d7288ea9 
> com.sun.jini.landlord.ConstrainableLandlordLease@2fbb16ee
> LeaseGrantTestBase.logRequest INFO:     req:1,366,283,680,723
> LeaseGrantTestBase.logRequest INFO:     got:1,366,283,680,723
> LeaseGrantTestBase.logRequest INFO:     aprox duration:60,000
> LeaseGrantTestBase.logRequest INFO:     drift:0
> LeaseUsesTestBase.run FINEST: postTime: 1,366,283,620,739, (expTime - 
> slop): 1,366,283,677,723
> LeaseUsesTestBase.cancel INFO: Cancel Test: checking for availability
> LeaseUsesTestBase.cancel INFO: Cancel Test: canceling lease
> NonActGrp-out: net.jini.core.transaction.TimeoutExpiredException: 
> timeout expired
> NonActGrp-out:     at 
> com.sun.jini.mahalo.TxnManagerTransaction.abort(TxnManagerTransaction.java:1033)
> NonActGrp-out:     at 
> com.sun.jini.mahalo.TxnManagerImpl.abort(TxnManagerImpl.java:795)
> NonActGrp-out:     at 
> com.sun.jini.mahalo.TxnManagerImpl.abort(TxnManagerImpl.java:741)
> NonActGrp-out:     at 
> com.sun.jini.mahalo.TxnManagerImpl.cancel(TxnManagerImpl.java:1047)
> NonActGrp-out:     at 
> sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> NonActGrp-out:     at 
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> NonActGrp-out:     at 
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> NonActGrp-out:     at java.lang.reflect.Method.invoke(Method.java:597)
> NonActGrp-out:     at 
> net.jini.jeri.BasicInvocationDispatcher.invoke(BasicInvocationDispatcher.java:1134)
> NonActGrp-out:     at 
> net.jini.jeri.BasicInvocationDispatcher.dispatch(BasicInvocationDispatcher.java:610)
> NonActGrp-out:     at 
> com.sun.jini.jeri.internal.runtime.Target$2.run(Target.java:491)
> NonActGrp-out:     at 
> net.jini.export.ServerContext.doWithServerContext(ServerContext.java:108)
> NonActGrp-out:     at 
> com.sun.jini.jeri.internal.runtime.Target.dispatch(Target.java:488)
> NonActGrp-out:     at 
> com.sun.jini.jeri.internal.runtime.Target.access$000(Target.java:57)
> NonActGrp-out:     at 
> com.sun.jini.jeri.internal.runtime.Target$1.run(Target.java:464)
> NonActGrp-out:     at 
> com.sun.jini.start.AggregatePolicyProvider$AggregateSecurityContext$2.run(AggregatePolicyProvider.java:593)
> NonActGrp-out:     at 
> java.security.AccessController.doPrivileged(Native Method)
> NonActGrp-out:     at 
> com.sun.jini.jeri.internal.runtime.Target.dispatch(Target.java:461)
> NonActGrp-out:     at 
> com.sun.jini.jeri.internal.runtime.Target.dispatch(Target.java:426)
> NonActGrp-out:     at 
> com.sun.jini.jeri.internal.runtime.DgcRequestDispatcher.dispatch(DgcRequestDispatcher.java:210)
> NonActGrp-out:     at 
> net.jini.jeri.connection.ServerConnectionManager$Dispatcher.dispatch(ServerConnectionManager.java:147)
> NonActGrp-out:     at 
> com.sun.jini.jeri.internal.mux.MuxServer$1$1.run(MuxServer.java:244)
> NonActGrp-out:     at 
> com.sun.jini.start.AggregatePolicyProvider$AggregateSecurityContext$1.run(AggregatePolicyProvider.java:579)
> NonActGrp-out:     at 
> java.security.AccessController.doPrivileged(Native Method)
> NonActGrp-out:     at 
> com.sun.jini.jeri.internal.mux.MuxServer$1.run(MuxServer.java:241)
> NonActGrp-out:     at 
> com.sun.jini.thread.ThreadPool$Task.run(ThreadPool.java:143)
> NonActGrp-out:     at 
> com.sun.jini.thread.ThreadPool$Worker.run(ThreadPool.java:187)
> NonActGrp-out:     at java.lang.Thread.run(Thread.java:662)
> LeaseUsesTestBase.cancel INFO: Sleeping for 1,000 milliseconds to 
> allow cancel to propagate...
> LeaseUsesTestBase.cancel INFO: awake
> LeaseUsesTestBase.cancel INFO: Cancel Test: checking to make sure 
> resource is gone
> com.sun.jini.qa.harness.TestException: Resource was available after 
> cancel
>     at 
> com.sun.jini.test.impl.outrigger.leasing.LeaseUsesTestBase.cancel(LeaseUsesTestBase.java:289)
>     at 
> com.sun.jini.test.impl.outrigger.leasing.LeaseUsesTestBase.run(LeaseUsesTestBase.java:242)
>     at com.sun.jini.qa.harness.MasterTest.doTest(MasterTest.java:256)
>     at com.sun.jini.qa.harness.MasterTest.main(MasterTest.java:144)
> MasterTest.doTest INFO:
> ============================ CALLING TEARDOWN() 
> =============================
>
>
> TIME: 9:14:08 PM
>
> TestBase.tearDown FINE: Waiting 0 ms after cleanup() call
> QATestEnvironment.tearDown FINE: Destroying remaining managed services
> AdminManager.destroyService FINE: destroying service: class 
> com.sun.jini.outrigger.ConstrainableSpaceProxy2
> AdminManager.destroyService FINE: destroying service: class 
> com.sun.jini.mahalo.TxnMgrProxy$ConstrainableTxnMgrProxy
> AdminManager.destroyService FINE: destroying service: class 
> com.sun.jini.reggie.ConstrainableRegistrarProxy
> AdminManager.destroyService FINE: destroying service: class 
> com.sun.jini.qa.harness.NonActivatableGroupImpl$GroupImpl_Stub
> NonActGrp-out: 18/04/2013 9:14:09 PM 
> com.sun.jini.thread.TaskManager$TaskThread run
> NonActGrp-out: WARNING: Task.run exception
> NonActGrp-out: java.lang.IllegalStateException: trying to add task to 
> stopped WakeupManager
> NonActGrp-out:     at 
> com.sun.jini.thread.WakeupManager.schedule(WakeupManager.java:431)
> NonActGrp-out:     at 
> com.sun.jini.thread.WakeupManager.schedule(WakeupManager.java:416)
> NonActGrp-out:     at 
> com.sun.jini.thread.RetryTask.run(RetryTask.java:153)
> NonActGrp-out:     at 
> com.sun.jini.thread.TaskManager$TaskThread.run(TaskManager.java:335)
> AdminManager.destroyService FINE: destroying service: class 
> com.sun.jini.tool.ClassServer
> 18/04/2013 9:14:10 PM com.sun.jini.tool.ClassServer terminate
> INFO: ClassServer terminated [port 9081]
> AdminManager.destroyService FINE: destroying service: class 
> com.sun.jini.tool.ClassServer
> 18/04/2013 9:14:10 PM com.sun.jini.tool.ClassServer terminate
> INFO: ClassServer terminated [port 9081]
> 18/04/2013 9:14:10 PM com.sun.jini.tool.ClassServer terminate
> INFO: ClassServer terminated [port 9082]
> AdminManager.destroyService FINE: destroying service: class 
> com.sun.jini.tool.ClassServer
> 18/04/2013 9:14:10 PM com.sun.jini.tool.ClassServer terminate
> INFO: ClassServer terminated [port 9082]
> 18/04/2013 9:14:10 PM com.sun.jini.tool.ClassServer terminate
> INFO: ClassServer terminated [port 9080]
>
> TIME: 9:14:10 PM
>
> Test process was destroyed and returned code 1
> com/sun/jini/test/impl/outrigger/leasing/UseTxnMgrSpaceLeaseTestRenewCancel.td 
>
> Test Failed: Test Failed: com.sun.jini.qa.harness.TestException: 
> Resource was available after cancel
>
>
> -----------------------------------------
>
> SUMMARY =================================
>
> com/sun/jini/test/impl/outrigger/leasing/UseTxnMgrSpaceLeaseTestRenewCancel.td 
>
> Test Failed: Test Failed: com.sun.jini.qa.harness.TestException: 
> Resource was available after cancel
>
> -----------------------------------------
>
> # of tests started   = 1
> # of tests completed = 1
> # of tests passed    = 0
> # of tests failed    = 1
>
> -----------------------------------------
>
>    Date finished:
>       Thu Apr 18 21:14:15 EST 2013
>    Time elapsed:
>       101 seconds
>
> Java Result: 1
> qa.collect-result:
> C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\build.xml:2105: 
> The following error occurred while executing this line:
> C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\build.xml:357: 
> condition satisfied
> BUILD FAILED (total time: 1 minute 43 seconds)