Author: peter_firmstone Date: Thu May 16 08:47:07 2013 New Revision: 1483250
URL: http://svn.apache.org/r1483250 Log: Add synchronization to test, removed volatile previously added to ensure visibility. Added additional log output to assist debugging random test failures on Arm, I'm unable to generate this test failure on other architectures. Additional logging occurs after failure, so won't affect the outcome of the test. Modified: river/jtsk/skunk/qa_refactor/trunk/qa/src/com/sun/jini/test/impl/outrigger/leasing/LeaseGrantTestBase.java river/jtsk/skunk/qa_refactor/trunk/qa/src/com/sun/jini/test/impl/outrigger/leasing/LeaseUsesTestBase.java river/jtsk/skunk/qa_refactor/trunk/qa/src/com/sun/jini/test/impl/outrigger/leasing/UseNotifyLeaseTest.java Modified: river/jtsk/skunk/qa_refactor/trunk/qa/src/com/sun/jini/test/impl/outrigger/leasing/LeaseGrantTestBase.java URL: http://svn.apache.org/viewvc/river/jtsk/skunk/qa_refactor/trunk/qa/src/com/sun/jini/test/impl/outrigger/leasing/LeaseGrantTestBase.java?rev=1483250&r1=1483249&r2=1483250&view=diff ============================================================================== --- river/jtsk/skunk/qa_refactor/trunk/qa/src/com/sun/jini/test/impl/outrigger/leasing/LeaseGrantTestBase.java (original) +++ river/jtsk/skunk/qa_refactor/trunk/qa/src/com/sun/jini/test/impl/outrigger/leasing/LeaseGrantTestBase.java Thu May 16 08:47:07 2013 @@ -199,30 +199,33 @@ public abstract class LeaseGrantTestBase */ protected void parse() throws Exception { super.parse(); - exact = getConfig().getBooleanConfigVal("com.sun.jini.test.share.exact", false); - clip = getConfig().getLongConfigVal("com.sun.jini.test.share.clip", -1); - slop = getConfig().getLongConfigVal("com.sun.jini.test.share.slop", 1000); - final String durStr = getConfig().getStringConfigVal("com.sun.jini.test.share.duration", null); + synchronized (this){ + QAConfig config = getConfig(); + exact = config.getBooleanConfigVal("com.sun.jini.test.share.exact", false); + clip = config.getLongConfigVal("com.sun.jini.test.share.clip", -1); + slop = config.getLongConfigVal("com.sun.jini.test.share.slop", 1000); + final String durStr = config.getStringConfigVal("com.sun.jini.test.share.duration", null); - if (durStr == null) { - durationRequest = 1000 * 60; - } else if (durStr.equals("forever")) { - durationRequest = Lease.FOREVER; - } else if (durStr.equals("anylength")) { - durationRequest = Lease.ANY; - } else { - try { - durationRequest = Long.parseLong(durStr); - } catch (NumberFormatException e) { - throw new Exception("Malformed argument for -duration property"); + if (durStr == null) { + durationRequest = 1000 * 60; + } else if (durStr.equals("forever")) { + durationRequest = Lease.FOREVER; + } else if (durStr.equals("anylength")) { + durationRequest = Lease.ANY; + } else { + try { + durationRequest = Long.parseLong(durStr); + } catch (NumberFormatException e) { + throw new Exception("Malformed argument for -duration property"); + } } - } - // Log out test options. - logger.log(Level.INFO, "exact = {0}", exact); - logger.log(Level.INFO, "clip = {0}", clip); - logger.log(Level.INFO, "slop = {0}", slop); - logger.log(Level.INFO, "durationRequest = {0}", durationRequest); + // Log out test options. + logger.log(Level.INFO, "exact = {0}", exact); + logger.log(Level.INFO, "clip = {0}", clip); + logger.log(Level.INFO, "slop = {0}", slop); + logger.log(Level.INFO, "durationRequest = {0}", durationRequest); + } } /** Modified: river/jtsk/skunk/qa_refactor/trunk/qa/src/com/sun/jini/test/impl/outrigger/leasing/LeaseUsesTestBase.java URL: http://svn.apache.org/viewvc/river/jtsk/skunk/qa_refactor/trunk/qa/src/com/sun/jini/test/impl/outrigger/leasing/LeaseUsesTestBase.java?rev=1483250&r1=1483249&r2=1483250&view=diff ============================================================================== --- river/jtsk/skunk/qa_refactor/trunk/qa/src/com/sun/jini/test/impl/outrigger/leasing/LeaseUsesTestBase.java (original) +++ river/jtsk/skunk/qa_refactor/trunk/qa/src/com/sun/jini/test/impl/outrigger/leasing/LeaseUsesTestBase.java Thu May 16 08:47:07 2013 @@ -46,22 +46,22 @@ public abstract class LeaseUsesTestBase /** * Lease being used */ - private volatile Lease lease = null; + private Lease lease = null; // Time lease will expire - private volatile long expTime; + private long expTime; // Time lease of lease duration - private volatile long durTime; + private long durTime; // How long until the lease should be renewed - private volatile long renewTime; + private long renewTime; // What to set renewTime to, if < 0 the half of duration - private volatile long renewWait; + private long renewWait; // Time to let cancel to propgate - private volatile long cancelSlop; + private long cancelSlop; // Set renew and exp times private void setTimes() { @@ -75,10 +75,10 @@ public abstract class LeaseUsesTestBase renewTime = renewWait + curTime; } } - private final AtomicLong renewals = new AtomicLong(); - private volatile boolean cancel; - private volatile long shutdownTime = -1; - private volatile long restartSleep = 10000; + private long renewals = 0; + private boolean cancel; + private long shutdownTime = -1; + private long restartSleep = 10000; /** * Method should acquire some resource under a lease and return @@ -127,25 +127,27 @@ public abstract class LeaseUsesTestBase */ protected void parse() throws Exception { super.parse(); - - // Get values from property file for this test. - renewals.set(getConfig().getIntConfigVal("com.sun.jini.test.share.renew", 0)); - cancel = getConfig().getBooleanConfigVal("com.sun.jini.test.share.cancel", false); - renewWait = getConfig().getLongConfigVal("com.sun.jini.test.share.renew_wait", -1); - shutdownTime = getConfig().getLongConfigVal("com.sun.jini.test.share.shutdownTime", -1); - restartSleep = getConfig().getLongConfigVal("com.sun.jini.test.share.restartSleep", 10000); - cancelSlop = getConfig().getLongConfigVal("com.sun.jini.test.share.cancel_slop", 0); - - // Log out test options. - logger.log(Level.INFO, "renewals = {0}", renewals); - logger.log(Level.INFO, "cancel = {0}", cancel); - logger.log(Level.INFO, "renewWait = {0}", renewWait); - logger.log(Level.INFO, "shutdownTime = {0}", shutdownTime); - logger.log(Level.INFO, "restartSleep = {0}", restartSleep); - logger.log(Level.INFO, "cancelSlop = {0}", cancelSlop); + synchronized (this){ + // Get values from property file for this test. + QAConfig config = getConfig(); + renewals = config.getIntConfigVal("com.sun.jini.test.share.renew", 0); + cancel = config.getBooleanConfigVal("com.sun.jini.test.share.cancel", false); + renewWait = config.getLongConfigVal("com.sun.jini.test.share.renew_wait", -1); + shutdownTime = config.getLongConfigVal("com.sun.jini.test.share.shutdownTime", -1); + restartSleep = config.getLongConfigVal("com.sun.jini.test.share.restartSleep", 10000); + cancelSlop = config.getLongConfigVal("com.sun.jini.test.share.cancel_slop", 0); + + // Log out test options. + logger.log(Level.INFO, "renewals = {0}", renewals); + logger.log(Level.INFO, "cancel = {0}", cancel); + logger.log(Level.INFO, "renewWait = {0}", renewWait); + logger.log(Level.INFO, "shutdownTime = {0}", shutdownTime); + logger.log(Level.INFO, "restartSleep = {0}", restartSleep); + logger.log(Level.INFO, "cancelSlop = {0}", cancelSlop); + } } - public void run() throws Exception { + public synchronized void run() throws Exception { lease = acquireResource(); addLease(lease, true); setTimes(); @@ -161,7 +163,7 @@ public abstract class LeaseUsesTestBase throw new TestException("Lease had an improper duration"); } - if (cancel && renewals.get() <= 0) { + if (cancel && renewals <= 0) { cancel(); } else { logger.log(Level.INFO, "Expire Test: Slop = {0}", slop); @@ -192,42 +194,43 @@ public abstract class LeaseUsesTestBase final long preTime = System.currentTimeMillis(); final boolean stillThere; final long postTime; - synchronized (this){ - stillThere = isAvailable(); - - /* - * We also use postTime as an approximation of the - * current time for the remainder of this iteration - */ - postTime = System.currentTimeMillis(); + stillThere = isAvailable(); - /* - * Check for late expiration against preTime - * postTime - slop elemnates overflow problems when - * expTime == FOREVER - */ - if (stillThere && (preTime - slop > expTime)) { - throw new TestException( - "Resource was available after lease expiration"); - } + /* + * We also use postTime as an approximation of the + * current time for the remainder of this iteration + */ + postTime = System.currentTimeMillis(); + /* + * Check for late expiration against preTime + * postTime - slop elemnates overflow problems when + * expTime == FOREVER + */ + if (stillThere && (preTime - slop > expTime)) { // Check for early expiration against postTime - logger.log(Level.FINEST, "postTime: {0}, (expTime - slop): {1}", - new Object[]{postTime, expTime - slop}); - if (!stillThere && (postTime < expTime - slop)) { - throw new TestException( - "Resource was not available before lease expiration"); - } + logger.log(Level.WARNING, "expTime: {0}, (preTime - slop): {1}, still there: {2}", + new Object[]{expTime, preTime - slop, stillThere}); + throw new TestException( + "Resource was available after lease expiration"); + } - if (!stillThere) { - // No use testing once it is gone - break; - } + if (!stillThere && (postTime < expTime - slop)) { + // Check for early expiration against postTime + logger.log(Level.WARNING, "postTime: {0}, (expTime - slop): {1}, still there: {2}", + new Object[]{postTime, expTime - slop, stillThere}); + throw new TestException( + "Resource was not available before lease expiration"); } + if (!stillThere) { + + // No use testing once it is gone + break; + } // Do we need to renew - if (renewals.get() > 0 && postTime > renewTime) { + if (renewals > 0 && postTime > renewTime) { lease.renew(durationRequest); resourceRequested(); setTimes(); @@ -237,8 +240,8 @@ public abstract class LeaseUsesTestBase throw new TestException( "Renewed lease had an improper duration"); } - renewals.decrementAndGet(); - } else if (renewals.get() == 0 && cancel) { + renewals--; + } else if (renewals == 0 && cancel) { cancel(); /* @@ -267,20 +270,21 @@ public abstract class LeaseUsesTestBase if (!isAvailable()) { throw new TestException("Resource was never available"); } - - logger.log(Level.INFO, "Cancel Test: canceling lease"); - lease.cancel(); - - /* - * We could poll and loop here, but one big sleep is much - * easer to code - */ - if (cancelSlop > 0) { - logger.log(Level.INFO, - "Sleeping for {0}" + " milliseconds to " - + "allow cancel to propagate... time: {1}", new Object[] {cancelSlop, System.currentTimeMillis()}); - Thread.sleep(cancelSlop); - logger.log(Level.INFO, "awake: {0}", System.currentTimeMillis()); + synchronized (this){ + logger.log(Level.INFO, "Cancel Test: canceling lease"); + lease.cancel(); + + /* + * We could poll and loop here, but one big sleep is much + * easer to code + */ + if (cancelSlop > 0) { + logger.log(Level.INFO, + "Sleeping for {0}" + " milliseconds to " + + "allow cancel to propagate... time: {1}", new Object[] {cancelSlop, System.currentTimeMillis()}); + Thread.sleep(cancelSlop); + logger.log(Level.INFO, "awake: {0}", System.currentTimeMillis()); + } } logger.log(Level.INFO, "Cancel Test: checking to make sure resource " + "is gone"); Modified: river/jtsk/skunk/qa_refactor/trunk/qa/src/com/sun/jini/test/impl/outrigger/leasing/UseNotifyLeaseTest.java URL: http://svn.apache.org/viewvc/river/jtsk/skunk/qa_refactor/trunk/qa/src/com/sun/jini/test/impl/outrigger/leasing/UseNotifyLeaseTest.java?rev=1483250&r1=1483249&r2=1483250&view=diff ============================================================================== --- river/jtsk/skunk/qa_refactor/trunk/qa/src/com/sun/jini/test/impl/outrigger/leasing/UseNotifyLeaseTest.java (original) +++ river/jtsk/skunk/qa_refactor/trunk/qa/src/com/sun/jini/test/impl/outrigger/leasing/UseNotifyLeaseTest.java Thu May 16 08:47:07 2013 @@ -42,10 +42,10 @@ import java.util.concurrent.atomic.Atomi */ public class UseNotifyLeaseTest extends LeaseUsesTestBase { final private Entry aEntry = new UninterestingEntry(); - private volatile LeasedSpaceListener listener; - private volatile JavaSpace space; - private volatile long callbackWait; - private volatile boolean verbose; + private LeasedSpaceListener listener; + private JavaSpace space; + private long callbackWait; + private boolean verbose; /** * Parse our args @@ -61,67 +61,68 @@ public class UseNotifyLeaseTest extends */ protected void parse() throws Exception { super.parse(); - - // Get values from property file for this test. - callbackWait = getConfig().getLongConfigVal("com.sun.jini.test.share.callbackWait", 2000); - verbose = getConfig().getBooleanConfigVal("com.sun.jini.test.share.verbose", false); - - // Log out test options. - logger.log(Level.INFO, "callbackWait = " + callbackWait); - logger.log(Level.INFO, "verbose = " + verbose); + synchronized (this){ + // Get values from property file for this test. + callbackWait = getConfig().getLongConfigVal("com.sun.jini.test.share.callbackWait", 2000); + verbose = getConfig().getBooleanConfigVal("com.sun.jini.test.share.verbose", false); + + // Log out test options. + logger.log(Level.INFO, "callbackWait = " + callbackWait); + logger.log(Level.INFO, "verbose = " + verbose); + } } protected Lease acquireResource() throws TestException { - specifyServices(new Class[] { - JavaSpace.class}); + specifyServices(new Class[] {JavaSpace.class}); prep(0); Lease lease = null; - try { - listener = new LeasedSpaceListener(getConfig().getConfiguration()); - space = (JavaSpace) services[0]; - JavaSpace space = this.space; - LeasedSpaceListener listener = this.listener; - EventRegistration reg = space.notify(aEntry, null, listener, - durationRequest, null); - reg = (EventRegistration) - getConfig().prepare("test.outriggerEventRegistrationPreparer", - reg); - resourceRequested(); - lease = reg.getLease(); - lease = (Lease) - getConfig().prepare("test.outriggerLeasePreparer", - lease); + synchronized (this){ + listener = new LeasedSpaceListener(getConfig().getConfiguration()); + space = (JavaSpace) services[0]; + JavaSpace space = this.space; + LeasedSpaceListener listener = this.listener; + EventRegistration reg = space.notify(aEntry, null, listener, + durationRequest, null); + reg = (EventRegistration) + getConfig().prepare("test.outriggerEventRegistrationPreparer", + reg); + resourceRequested(); + lease = reg.getLease(); + lease = (Lease) + getConfig().prepare("test.outriggerLeasePreparer", + lease); + } } catch (Exception e) { throw new TestException("registering for event", e); } return lease; } - private final AtomicInteger count = new AtomicInteger(); + private int count = 0; protected boolean isAvailable() throws TestException { try { - logger.log(Level.FINEST, "Writing entry {0}", count.getAndIncrement()); - LeasedSpaceListener listener = this.listener; - JavaSpace space = this.space; - synchronized (listener) { // Can't synchronize on volatile field. - listener.setReceived(false); - - /* - * Important to have the write inside the - * synchronized, otherwise we my miss - * listener.received transtion from false->true - */ - addOutriggerLease(space.write(aEntry, null, Lease.ANY), false); - /* Check for spurious wakeup */ - long startTime = System.currentTimeMillis(); - long finishTime = startTime + callbackWait; - while (System.currentTimeMillis() < finishTime) { - logger.log(Level.FINEST, "Waiting for listener to be called at {0}", (new java.util.Date())); - listener.wait(callbackWait); - if (listener.isReceived()){ - logger.log(Level.FINEST, "Wait done at {0}, received = {1}", new Object[]{new java.util.Date(), listener.isReceived()}); - return true; + synchronized (this){ + logger.log(Level.FINEST, "Writing entry {0}", ++count); + synchronized (listener) { + listener.setReceived(false); + + /* + * Important to have the write inside the + * synchronized, otherwise we my miss + * listener.received transtion from false->true + */ + addOutriggerLease(space.write(aEntry, null, Lease.ANY), false); + /* Check for spurious wakeup */ + long startTime = System.currentTimeMillis(); + long finishTime = startTime + callbackWait; + while (System.currentTimeMillis() < finishTime) { + logger.log(Level.FINEST, "Waiting for listener to be called at {0}", (new java.util.Date())); + listener.wait(callbackWait); + if (listener.isReceived()){ + logger.log(Level.FINEST, "Wait done at {0}, received = {1}", new Object[]{new java.util.Date(), listener.isReceived()}); + return true; + } } } }
