Merged HEAD (5.1) to 5.1.N (5.1.1)

114288 sglover: ACE-4347 "5.1 Build has had three transient failures related to locking"
   Increase the logging for the failing tests to DEBUG so that we can see what's happening during the next failure


git-svn-id: https://svn.alfresco.com/repos/alfresco-enterprise/alfresco/BRANCHES/DEV/5.1.N/root@114402 c4b6b30b-aa2e-2d43-bbcb-ca4b014f7261

source/test-java/org/alfresco/repo/lock/JobLockServiceTest.java

@@ -31,6 +31,8 @@ import org.alfresco.test_category.OwnJVMTestsCategory;
 import org.alfresco.util.ApplicationContextHelper;
 import org.apache.commons.logging.Log;
 import org.apache.commons.logging.LogFactory;
+import org.apache.log4j.Level;
+import org.apache.log4j.Logger;
 import org.junit.experimental.categories.Category;
 import org.springframework.context.ApplicationContext;
 
@@ -356,50 +358,61 @@ public class JobLockServiceTest extends TestCase
     
     public synchronized void testLockCallbackReleaseSelf() throws Exception
     {
-        final QName lockQName = QName.createQName(NAMESPACE, getName());
+        // ACE-4347 extra debug logging just for this test so we can see what's going on when it next fails
-        final long lockTTL = 1000L;
+        Level saveLogLevel = Logger.getLogger("org.alfresco.repo.lock").getLevel();
-        final String lockToken = jobLockService.getLock(lockQName, lockTTL);
+        Logger.getLogger("org.alfresco.repo.lock").setLevel(Level.ALL);
-
-        final int[] checked = new int[1];
-        final int[] released = new int[1];
-        // Immediately-inactive job, releasing the lock
-        JobLockRefreshCallback callback = new JobLockRefreshCallback()
-        {
-            @Override
-            public boolean isActive()
-            {
-                checked[0]++;
-                jobLockService.releaseLock(lockToken, lockQName);
-                return false;
-            }
-            
-            @Override
-            public void lockReleased()
-            {
-                released[0]++;
-            }
-        };
-
-        jobLockService.refreshLock(lockToken, lockQName, lockTTL, callback);
-        // The first refresh will occur in 500ms
-        wait(1000L);
-        // Should NOT get a callback saying that the lock has been released
-        assertFalse("Lock should be optimistically released", released[0] > 0);
         try
         {
-            jobLockService.getLock(lockQName, lockTTL);
+            final QName lockQName = QName.createQName(NAMESPACE, getName());
-        }
+            final long lockTTL = 1000L;
-        catch (LockAcquisitionException e)
+            final String lockToken = jobLockService.getLock(lockQName, lockTTL);
-        {
-            fail("Lock should have been released by callback infrastructure");
-        }
     
-        // Check that the timed callback is killed properly
+            final int[] checked = new int[1];
-        int checkedCount = checked[0];
+            final int[] released = new int[1];
-        int releasedCount = released[0];
+            // Immediately-inactive job, releasing the lock
-        wait(2000L);
+            JobLockRefreshCallback callback = new JobLockRefreshCallback()
-        assertEquals("Lock callback timer was not terminated", checkedCount, checked[0]);
+            {
-        assertEquals("Lock callback timer was not terminated", releasedCount, released[0]);
+                @Override
+                public boolean isActive()
+                {
+                    checked[0]++;
+                    jobLockService.releaseLock(lockToken, lockQName);
+                    return false;
+                }
+                
+                @Override
+                public void lockReleased()
+                {
+                    released[0]++;
+                }
+            };
+    
+            jobLockService.refreshLock(lockToken, lockQName, lockTTL, callback);
+            // The first refresh will occur in 500ms
+            wait(1000L);
+            // Should NOT get a callback saying that the lock has been released
+            assertFalse("Lock should be optimistically released", released[0] > 0);
+            try
+            {
+                jobLockService.getLock(lockQName, lockTTL);
+            }
+            catch (LockAcquisitionException e)
+            {
+                fail("Lock should have been released by callback infrastructure");
+            }
+            
+            // Check that the timed callback is killed properly
+            int checkedCount = checked[0];
+            int releasedCount = released[0];
+            System.out.println("X:" + checkedCount + ":" + releasedCount);
+            wait(10000L);
+            assertEquals("Lock callback timer was not terminated", checkedCount, checked[0]);
+            assertEquals("Lock callback timer was not terminated", releasedCount, released[0]);
+        }
+        finally
+        {
+            Logger.getLogger("org.alfresco.repo.lock").setLevel(saveLogLevel);
+        }
     }
     
     /**