Console Output
Skipping 609 KB..
Full Loge.MergeExecutorService[357] - Connect to nowhere timed out"
INFO [main] 2015-07-24 16:56:15,390 o.d.tidy.merge.MergeExecutorService[243] - ExecutionException retryJob has resourceMap_kgordon.35.49
DEBUG[main] 2015-07-24 16:56:15,391 o.d.tidy.merge.MergeExecutorService[348] - org.dataone.service.exceptions.ServiceFailure: class java.net.SocketTimeoutException: Connect to nowhere timed out"
DEBUG[main] 2015-07-24 16:56:15,391 o.d.tidy.merge.MergeExecutorService[357] - class java.net.SocketTimeoutException: Connect to nowhere timed out"
DEBUG[main] 2015-07-24 16:56:15,391 o.d.tidy.merge.MergeExecutorService[357] - Connect to nowhere timed out"
INFO [main] 2015-07-24 16:56:15,392 o.d.tidy.merge.MergeExecutorService[315] - retry resourceMap_kgordon.35.49 with count 2
INFO [main] 2015-07-24 16:56:15,392 o.d.tidy.merge.MergeExecutorService[243] - ExecutionException retryJob has resourceMap_jimont.132.5
DEBUG[main] 2015-07-24 16:56:15,392 o.d.tidy.merge.MergeExecutorService[348] - org.dataone.service.exceptions.ServiceFailure: class java.net.SocketTimeoutException: Connect to nowhere timed out"
DEBUG[main] 2015-07-24 16:56:15,393 o.d.tidy.merge.MergeExecutorService[357] - class java.net.SocketTimeoutException: Connect to nowhere timed out"
DEBUG[main] 2015-07-24 16:56:15,393 o.d.tidy.merge.MergeExecutorService[357] - Connect to nowhere timed out"
INFO [main] 2015-07-24 16:56:15,393 o.d.tidy.merge.MergeExecutorService[315] - retry resourceMap_jimont.132.5 with count 2
INFO [main] 2015-07-24 16:56:15,394 o.d.tidy.merge.MergeExecutorService[243] - ExecutionException retryJob has resourceMap_jgoldberg.5.1
DEBUG[main] 2015-07-24 16:56:15,394 o.d.tidy.merge.MergeExecutorService[348] - org.dataone.service.exceptions.ServiceFailure: class java.net.SocketTimeoutException: Connect to nowhere timed out"
DEBUG[main] 2015-07-24 16:56:15,394 o.d.tidy.merge.MergeExecutorService[357] - class java.net.SocketTimeoutException: Connect to nowhere timed out"
DEBUG[main] 2015-07-24 16:56:15,394 o.d.tidy.merge.MergeExecutorService[357] - Connect to nowhere timed out"
INFO [main] 2015-07-24 16:56:15,395 o.d.tidy.merge.MergeExecutorService[315] - retry resourceMap_jgoldberg.5.1 with count 2
DEBUG[main] 2015-07-24 16:56:15,395 o.d.tidy.merge.MergeExecutorService[262] - TotalToProcess = 25 totalCompleted 0 totalFailed 22 total Unrecoverable 0
ERROR[pool-6-thread-3] 2015-07-24 16:56:15,397 o.d.t.c.TidyJobThreadPoolExecutor[123] - afterExecute: resourceMap_jgoldberg.5.1: java.util.concurrent.ExecutionException: org.dataone.service.exceptions.ServiceFailure: class java.net.SocketTimeoutException: Connect to nowhere timed out"
[2015-07-24T16:56:15.397+00:00] afterExecute: resourceMap_jgoldberg.5.1 StackTrace: java.util.concurrent.ExecutionException: org.dataone.service.exceptions.ServiceFailure: class java.net.SocketTimeoutException: Connect to nowhere timed out"
at java.util.concurrent.FutureTask.report(FutureTask.java:122)
at java.util.concurrent.FutureTask.get(FutureTask.java:188)
at org.dataone.tidy.concurrent.TidyJobThreadPoolExecutor.afterExecute(TidyJobThreadPoolExecutor.java:113)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1153)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Caused by: org.dataone.service.exceptions.ServiceFailure: class java.net.SocketTimeoutException: Connect to nowhere timed out"
at org.dataone.tidy.concurrent.MockExecutionTimeoutTidyJob.call(MockExecutionTimeoutTidyJob.java:20)
at org.dataone.tidy.concurrent.MockExecutionTimeoutTidyJob.call(MockExecutionTimeoutTidyJob.java:16)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
... 2 more
Caused by: java.net.SocketTimeoutException: Connect to nowhere timed out"
... 6 more
DEBUG[pool-6-thread-3] 2015-07-24 16:56:15,398 o.d.t.c.TidyJobThreadPoolExecutor[130] - job is of pid resourceMap_jgoldberg.5.1
ERROR[pool-6-thread-10] 2015-07-24 16:56:15,401 o.d.t.c.TidyJobThreadPoolExecutor[123] - afterExecute: resourceMap_jimont.132.5: java.util.concurrent.ExecutionException: org.dataone.service.exceptions.ServiceFailure: class java.net.SocketTimeoutException: Connect to nowhere timed out"
[2015-07-24T16:56:15.401+00:00] afterExecute: resourceMap_jimont.132.5 StackTrace: java.util.concurrent.ExecutionException: org.dataone.service.exceptions.ServiceFailure: class java.net.SocketTimeoutException: Connect to nowhere timed out"
at java.util.concurrent.FutureTask.report(FutureTask.java:122)
at java.util.concurrent.FutureTask.get(FutureTask.java:188)
at org.dataone.tidy.concurrent.TidyJobThreadPoolExecutor.afterExecute(TidyJobThreadPoolExecutor.java:113)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1153)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Caused by: org.dataone.service.exceptions.ServiceFailure: class java.net.SocketTimeoutException: Connect to nowhere timed out"
at org.dataone.tidy.concurrent.MockExecutionTimeoutTidyJob.call(MockExecutionTimeoutTidyJob.java:20)
at org.dataone.tidy.concurrent.MockExecutionTimeoutTidyJob.call(MockExecutionTimeoutTidyJob.java:16)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
... 2 more
Caused by: java.net.SocketTimeoutException: Connect to nowhere timed out"
... 6 more
DEBUG[pool-6-thread-10] 2015-07-24 16:56:15,402 o.d.t.c.TidyJobThreadPoolExecutor[130] - job is of pid resourceMap_jimont.132.5
ERROR[pool-6-thread-5] 2015-07-24 16:56:15,404 o.d.t.c.TidyJobThreadPoolExecutor[123] - afterExecute: resourceMap_kgordon.35.49: java.util.concurrent.ExecutionException: org.dataone.service.exceptions.ServiceFailure: class java.net.SocketTimeoutException: Connect to nowhere timed out"
[2015-07-24T16:56:15.404+00:00] afterExecute: resourceMap_kgordon.35.49 StackTrace: java.util.concurrent.ExecutionException: org.dataone.service.exceptions.ServiceFailure: class java.net.SocketTimeoutException: Connect to nowhere timed out"
at java.util.concurrent.FutureTask.report(FutureTask.java:122)
at java.util.concurrent.FutureTask.get(FutureTask.java:188)
at org.dataone.tidy.concurrent.TidyJobThreadPoolExecutor.afterExecute(TidyJobThreadPoolExecutor.java:113)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1153)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Caused by: org.dataone.service.exceptions.ServiceFailure: class java.net.SocketTimeoutException: Connect to nowhere timed out"
at org.dataone.tidy.concurrent.MockExecutionTimeoutTidyJob.call(MockExecutionTimeoutTidyJob.java:20)
at org.dataone.tidy.concurrent.MockExecutionTimeoutTidyJob.call(MockExecutionTimeoutTidyJob.java:16)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
... 2 more
Caused by: java.net.SocketTimeoutException: Connect to nowhere timed out"
... 6 more
DEBUG[pool-6-thread-5] 2015-07-24 16:56:15,405 o.d.t.c.TidyJobThreadPoolExecutor[130] - job is of pid resourceMap_kgordon.35.49
DEBUG[main] 2015-07-24 16:56:15,406 o.d.tidy.merge.MergeExecutorService[178] - after submit 79
ERROR[main] 2015-07-24 16:56:15,410 o.d.tidy.merge.MergeExecutorService[230] - java.util.concurrent.ExecutionException: org.dataone.service.exceptions.ServiceFailure: class java.net.SocketTimeoutException: Connect to nowhere timed out"
DEBUG[main] 2015-07-24 16:56:15,410 o.d.tidy.merge.MergeExecutorService[348] - org.dataone.service.exceptions.ServiceFailure: class java.net.SocketTimeoutException: Connect to nowhere timed out"
DEBUG[main] 2015-07-24 16:56:15,411 o.d.tidy.merge.MergeExecutorService[357] - class java.net.SocketTimeoutException: Connect to nowhere timed out"
DEBUG[main] 2015-07-24 16:56:15,411 o.d.tidy.merge.MergeExecutorService[357] - Connect to nowhere timed out"
INFO [main] 2015-07-24 16:56:15,411 o.d.tidy.merge.MergeExecutorService[243] - ExecutionException retryJob has resourceMap_kgordon.35.49
DEBUG[main] 2015-07-24 16:56:15,412 o.d.tidy.merge.MergeExecutorService[348] - org.dataone.service.exceptions.ServiceFailure: class java.net.SocketTimeoutException: Connect to nowhere timed out"
DEBUG[main] 2015-07-24 16:56:15,412 o.d.tidy.merge.MergeExecutorService[357] - class java.net.SocketTimeoutException: Connect to nowhere timed out"
DEBUG[main] 2015-07-24 16:56:15,412 o.d.tidy.merge.MergeExecutorService[357] - Connect to nowhere timed out"
INFO [main] 2015-07-24 16:56:15,413 o.d.tidy.merge.MergeExecutorService[315] - retry resourceMap_kgordon.35.49 with count 3
WARN [main] 2015-07-24 16:56:15,413 o.d.tidy.merge.MergeExecutorService[318] - fail count exceeded removing job from retry, adding to failedPidSet: resourceMap_kgordon.35.49
[2015-07-24T16:56:15.413+00:00] no retry executeJobs: java.util.concurrent.ExecutionException java.util.concurrent.ExecutionException: org.dataone.service.exceptions.ServiceFailure: class java.net.SocketTimeoutException: Connect to nowhere timed out"
at java.util.concurrent.FutureTask.report(FutureTask.java:122)
at java.util.concurrent.FutureTask.get(FutureTask.java:188)
at org.dataone.tidy.merge.MergeExecutorService.executeJobs(MergeExecutorService.java:181)
at org.dataone.tidy.merge.MergeExecutorServiceTest.executeExecutionTimeoutMergeExecuturServiceTest(MergeExecutorServiceTest.java:155)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:45)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:42)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:263)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:68)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:47)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:60)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:229)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:50)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222)
at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
at org.junit.runners.ParentRunner.run(ParentRunner.java:300)
at org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:53)
at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:123)
at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:104)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.apache.maven.surefire.util.ReflectionUtils.invokeMethodWithArray(ReflectionUtils.java:164)
at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:110)
at org.apache.maven.surefire.booter.SurefireStarter.invokeProvider(SurefireStarter.java:175)
at org.apache.maven.surefire.booter.SurefireStarter.runSuitesInProcessWhenForked(SurefireStarter.java:107)
at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:68)
Caused by: org.dataone.service.exceptions.ServiceFailure: class java.net.SocketTimeoutException: Connect to nowhere timed out"
at org.dataone.tidy.concurrent.MockExecutionTimeoutTidyJob.call(MockExecutionTimeoutTidyJob.java:20)
at org.dataone.tidy.concurrent.MockExecutionTimeoutTidyJob.call(MockExecutionTimeoutTidyJob.java:16)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.net.SocketTimeoutException: Connect to nowhere timed out"
... 6 more
INFO [main] 2015-07-24 16:56:15,424 o.d.tidy.merge.MergeExecutorService[243] - ExecutionException retryJob has resourceMap_jimont.132.5
DEBUG[main] 2015-07-24 16:56:15,425 o.d.tidy.merge.MergeExecutorService[348] - org.dataone.service.exceptions.ServiceFailure: class java.net.SocketTimeoutException: Connect to nowhere timed out"
DEBUG[main] 2015-07-24 16:56:15,425 o.d.tidy.merge.MergeExecutorService[357] - class java.net.SocketTimeoutException: Connect to nowhere timed out"
DEBUG[main] 2015-07-24 16:56:15,425 o.d.tidy.merge.MergeExecutorService[357] - Connect to nowhere timed out"
INFO [main] 2015-07-24 16:56:15,425 o.d.tidy.merge.MergeExecutorService[315] - retry resourceMap_jimont.132.5 with count 3
WARN [main] 2015-07-24 16:56:15,426 o.d.tidy.merge.MergeExecutorService[318] - fail count exceeded removing job from retry, adding to failedPidSet: resourceMap_jimont.132.5
[2015-07-24T16:56:15.426+00:00] no retry executeJobs: java.util.concurrent.ExecutionException java.util.concurrent.ExecutionException: org.dataone.service.exceptions.ServiceFailure: class java.net.SocketTimeoutException: Connect to nowhere timed out"
at java.util.concurrent.FutureTask.report(FutureTask.java:122)
at java.util.concurrent.FutureTask.get(FutureTask.java:188)
at org.dataone.tidy.merge.MergeExecutorService.executeJobs(MergeExecutorService.java:181)
at org.dataone.tidy.merge.MergeExecutorServiceTest.executeExecutionTimeoutMergeExecuturServiceTest(MergeExecutorServiceTest.java:155)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:45)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:42)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:263)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:68)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:47)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:60)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:229)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:50)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222)
at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
at org.junit.runners.ParentRunner.run(ParentRunner.java:300)
at org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:53)
at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:123)
at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:104)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.apache.maven.surefire.util.ReflectionUtils.invokeMethodWithArray(ReflectionUtils.java:164)
at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:110)
at org.apache.maven.surefire.booter.SurefireStarter.invokeProvider(SurefireStarter.java:175)
at org.apache.maven.surefire.booter.SurefireStarter.runSuitesInProcessWhenForked(SurefireStarter.java:107)
at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:68)
Caused by: org.dataone.service.exceptions.ServiceFailure: class java.net.SocketTimeoutException: Connect to nowhere timed out"
at org.dataone.tidy.concurrent.MockExecutionTimeoutTidyJob.call(MockExecutionTimeoutTidyJob.java:20)
at org.dataone.tidy.concurrent.MockExecutionTimeoutTidyJob.call(MockExecutionTimeoutTidyJob.java:16)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.net.SocketTimeoutException: Connect to nowhere timed out"
... 6 more
INFO [main] 2015-07-24 16:56:15,437 o.d.tidy.merge.MergeExecutorService[243] - ExecutionException retryJob has resourceMap_jgoldberg.5.1
DEBUG[main] 2015-07-24 16:56:15,437 o.d.tidy.merge.MergeExecutorService[348] - org.dataone.service.exceptions.ServiceFailure: class java.net.SocketTimeoutException: Connect to nowhere timed out"
DEBUG[main] 2015-07-24 16:56:15,438 o.d.tidy.merge.MergeExecutorService[357] - class java.net.SocketTimeoutException: Connect to nowhere timed out"
DEBUG[main] 2015-07-24 16:56:15,438 o.d.tidy.merge.MergeExecutorService[357] - Connect to nowhere timed out"
INFO [main] 2015-07-24 16:56:15,438 o.d.tidy.merge.MergeExecutorService[315] - retry resourceMap_jgoldberg.5.1 with count 3
WARN [main] 2015-07-24 16:56:15,439 o.d.tidy.merge.MergeExecutorService[318] - fail count exceeded removing job from retry, adding to failedPidSet: resourceMap_jgoldberg.5.1
[2015-07-24T16:56:15.439+00:00] no retry executeJobs: java.util.concurrent.ExecutionException java.util.concurrent.ExecutionException: org.dataone.service.exceptions.ServiceFailure: class java.net.SocketTimeoutException: Connect to nowhere timed out"
at java.util.concurrent.FutureTask.report(FutureTask.java:122)
at java.util.concurrent.FutureTask.get(FutureTask.java:188)
at org.dataone.tidy.merge.MergeExecutorService.executeJobs(MergeExecutorService.java:181)
at org.dataone.tidy.merge.MergeExecutorServiceTest.executeExecutionTimeoutMergeExecuturServiceTest(MergeExecutorServiceTest.java:155)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:45)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:42)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:263)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:68)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:47)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:60)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:229)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:50)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222)
at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
at org.junit.runners.ParentRunner.run(ParentRunner.java:300)
at org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:53)
at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:123)
at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:104)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.apache.maven.surefire.util.ReflectionUtils.invokeMethodWithArray(ReflectionUtils.java:164)
at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:110)
at org.apache.maven.surefire.booter.SurefireStarter.invokeProvider(SurefireStarter.java:175)
at org.apache.maven.surefire.booter.SurefireStarter.runSuitesInProcessWhenForked(SurefireStarter.java:107)
at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:68)
Caused by: org.dataone.service.exceptions.ServiceFailure: class java.net.SocketTimeoutException: Connect to nowhere timed out"
at org.dataone.tidy.concurrent.MockExecutionTimeoutTidyJob.call(MockExecutionTimeoutTidyJob.java:20)
at org.dataone.tidy.concurrent.MockExecutionTimeoutTidyJob.call(MockExecutionTimeoutTidyJob.java:16)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.net.SocketTimeoutException: Connect to nowhere timed out"
... 6 more
DEBUG[main] 2015-07-24 16:56:15,451 o.d.tidy.merge.MergeExecutorService[262] - TotalToProcess = 25 totalCompleted 0 totalFailed 25 total Unrecoverable 0
INFO [main] 2015-07-24 16:56:15,452 o.d.tidy.merge.MergeExecutorService[282] - Number of Jobs Successfuly Completed 0
INFO [main] 2015-07-24 16:56:15,452 o.d.tidy.merge.MergeExecutorService[283] - Number of Jobs on Failed 25
INFO [main] 2015-07-24 16:56:15,452 o.d.tidy.merge.MergeExecutorService[284] - Number of Jobs with Unrecoverable Exceptions 0
INFO [main] 2015-07-24 16:56:15,455 o.d.t.merge.MergeExecutorServiceTest[156] - 25 0 25
INFO [main] 2015-07-24 16:56:15,458 o.d.tidy.merge.MergeExecutorService[143] - Total pids to process = 2
DEBUG[main] 2015-07-24 16:56:16,463 o.d.tidy.merge.MergeExecutorService[178] - after submit 0
DEBUG[main] 2015-07-24 16:56:16,464 o.d.tidy.merge.MergeExecutorService[262] - TotalToProcess = 2 totalCompleted 0 totalFailed 0 total Unrecoverable 0
DEBUG[main] 2015-07-24 16:56:17,464 o.d.tidy.merge.MergeExecutorService[178] - after submit 0
DEBUG[main] 2015-07-24 16:56:17,465 o.d.tidy.merge.MergeExecutorService[262] - TotalToProcess = 2 totalCompleted 0 totalFailed 0 total Unrecoverable 0
DEBUG[main] 2015-07-24 16:56:18,465 o.d.tidy.merge.MergeExecutorService[178] - after submit 0
DEBUG[main] 2015-07-24 16:56:18,466 o.d.tidy.merge.MergeExecutorService[262] - TotalToProcess = 2 totalCompleted 0 totalFailed 0 total Unrecoverable 0
DEBUG[main] 2015-07-24 16:56:19,466 o.d.tidy.merge.MergeExecutorService[178] - after submit 0
ERROR[main] 2015-07-24 16:56:19,467 o.d.tidy.merge.MergeExecutorService[220] - waited over 3 seconds for any mergeJob to return, must be in an error state!
INFO [main] 2015-07-24 16:56:19,467 o.d.tidy.merge.MergeExecutorService[282] - Number of Jobs Successfuly Completed 0
INFO [main] 2015-07-24 16:56:19,467 o.d.tidy.merge.MergeExecutorService[283] - Number of Jobs on Failed 0
INFO [main] 2015-07-24 16:56:19,467 o.d.tidy.merge.MergeExecutorService[284] - Number of Jobs with Unrecoverable Exceptions 0
INFO [main] 2015-07-24 16:56:19,467 o.d.t.merge.MergeExecutorServiceTest[177] - 2 0 0
ERROR[pool-7-thread-2] 2015-07-24 16:56:19,468 o.d.t.c.TidyJobThreadPoolExecutor[123] - afterExecute: someid2: java.util.concurrent.ExecutionException: java.lang.InterruptedException: sleep interrupted
[2015-07-24T16:56:19.468+00:00] afterExecute: someid2 StackTrace: java.util.concurrent.ExecutionException: java.lang.InterruptedException: sleep interrupted
at java.util.concurrent.FutureTask.report(FutureTask.java:122)
at java.util.concurrent.FutureTask.get(FutureTask.java:188)
at org.dataone.tidy.concurrent.TidyJobThreadPoolExecutor.afterExecute(TidyJobThreadPoolExecutor.java:113)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1153)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.InterruptedException: sleep interrupted
at java.lang.Thread.sleep(Native Method)
at org.dataone.tidy.concurrent.MockFatalTidyJob.call(MockFatalTidyJob.java:17)
at org.dataone.tidy.concurrent.MockFatalTidyJob.call(MockFatalTidyJob.java:13)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
... 2 more
DEBUG[pool-7-thread-2] 2015-07-24 16:56:19,470 o.d.t.c.TidyJobThreadPoolExecutor[130] - job is of pid someid2
INFO [main] 2015-07-24 16:56:19,482 o.d.tidy.merge.MergeExecutorService[143] - Total pids to process = 14
ERROR[pool-7-thread-1] 2015-07-24 16:56:19,483 o.d.t.c.TidyJobThreadPoolExecutor[123] - afterExecute: someid1: java.util.concurrent.ExecutionException: java.lang.InterruptedException: sleep interrupted
[2015-07-24T16:56:19.483+00:00] afterExecute: someid1 StackTrace: java.util.concurrent.ExecutionException: java.lang.InterruptedException: sleep interrupted
at java.util.concurrent.FutureTask.report(FutureTask.java:122)
at java.util.concurrent.FutureTask.get(FutureTask.java:188)
at org.dataone.tidy.concurrent.TidyJobThreadPoolExecutor.afterExecute(TidyJobThreadPoolExecutor.java:113)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1153)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.InterruptedException: sleep interrupted
at java.lang.Thread.sleep(Native Method)
at org.dataone.tidy.concurrent.MockFatalTidyJob.call(MockFatalTidyJob.java:17)
at org.dataone.tidy.concurrent.MockFatalTidyJob.call(MockFatalTidyJob.java:13)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
... 2 more
DEBUG[pool-7-thread-1] 2015-07-24 16:56:19,487 o.d.t.c.TidyJobThreadPoolExecutor[130] - job is of pid someid1
DEBUG[main] 2015-07-24 16:56:19,987 o.d.tidy.merge.MergeExecutorService[178] - after submit 0
INFO [main] 2015-07-24 16:56:19,988 o.d.tidy.merge.MergeExecutorService[188] - Job Success: Blandy.76.2
DEBUG[main] 2015-07-24 16:56:19,988 o.d.tidy.merge.MergeExecutorService[262] - TotalToProcess = 14 totalCompleted 1 totalFailed 0 total Unrecoverable 0
DEBUG[pool-8-thread-1] 2015-07-24 16:56:19,988 o.d.t.c.TidyJobThreadPoolExecutor[130] - job is of pid Blandy.76.2
DEBUG[main] 2015-07-24 16:56:20,003 o.d.tidy.merge.MergeExecutorService[178] - after submit 0
DEBUG[pool-8-thread-2] 2015-07-24 16:56:20,003 o.d.t.c.TidyJobThreadPoolExecutor[130] - job is of pid Blandy.77.1
INFO [main] 2015-07-24 16:56:20,003 o.d.tidy.merge.MergeExecutorService[188] - Job Success: Blandy.77.1
DEBUG[main] 2015-07-24 16:56:20,004 o.d.tidy.merge.MergeExecutorService[262] - TotalToProcess = 14 totalCompleted 2 totalFailed 0 total Unrecoverable 0
DEBUG[main] 2015-07-24 16:56:20,011 o.d.tidy.merge.MergeExecutorService[178] - after submit 0
INFO [main] 2015-07-24 16:56:20,012 o.d.tidy.merge.MergeExecutorService[188] - Job Success: BrianGratwicke.4.1
DEBUG[main] 2015-07-24 16:56:20,012 o.d.tidy.merge.MergeExecutorService[262] - TotalToProcess = 14 totalCompleted 3 totalFailed 0 total Unrecoverable 0
DEBUG[pool-8-thread-5] 2015-07-24 16:56:20,011 o.d.t.c.TidyJobThreadPoolExecutor[130] - job is of pid cbfs.123.8
DEBUG[pool-8-thread-4] 2015-07-24 16:56:20,011 o.d.t.c.TidyJobThreadPoolExecutor[130] - job is of pid BrianGratwicke.4.1
DEBUG[main] 2015-07-24 16:56:20,012 o.d.tidy.merge.MergeExecutorService[178] - after submit 4
DEBUG[pool-8-thread-9] 2015-07-24 16:56:20,012 o.d.t.c.TidyJobThreadPoolExecutor[130] - job is of pid jgoldberg.4.1
DEBUG[pool-8-thread-8] 2015-07-24 16:56:20,012 o.d.t.c.TidyJobThreadPoolExecutor[130] - job is of pid datastar.117.6
DEBUG[pool-8-thread-7] 2015-07-24 16:56:20,012 o.d.t.c.TidyJobThreadPoolExecutor[130] - job is of pid cbfs.38.9
DEBUG[pool-8-thread-6] 2015-07-24 16:56:20,012 o.d.t.c.TidyJobThreadPoolExecutor[130] - job is of pid cbfs.131.4
INFO [main] 2015-07-24 16:56:20,013 o.d.tidy.merge.MergeExecutorService[188] - Job Success: cbfs.123.8
DEBUG[main] 2015-07-24 16:56:20,014 o.d.tidy.merge.MergeExecutorService[262] - TotalToProcess = 14 totalCompleted 4 totalFailed 0 total Unrecoverable 0
DEBUG[main] 2015-07-24 16:56:20,014 o.d.tidy.merge.MergeExecutorService[178] - after submit 4
INFO [main] 2015-07-24 16:56:20,014 o.d.tidy.merge.MergeExecutorService[188] - Job Success: cbfs.131.4
DEBUG[main] 2015-07-24 16:56:20,014 o.d.tidy.merge.MergeExecutorService[262] - TotalToProcess = 14 totalCompleted 5 totalFailed 0 total Unrecoverable 0
DEBUG[main] 2015-07-24 16:56:20,014 o.d.tidy.merge.MergeExecutorService[178] - after submit 3
INFO [main] 2015-07-24 16:56:20,015 o.d.tidy.merge.MergeExecutorService[188] - Job Success: cbfs.38.9
DEBUG[main] 2015-07-24 16:56:20,015 o.d.tidy.merge.MergeExecutorService[262] - TotalToProcess = 14 totalCompleted 6 totalFailed 0 total Unrecoverable 0
DEBUG[main] 2015-07-24 16:56:20,015 o.d.tidy.merge.MergeExecutorService[178] - after submit 2
INFO [main] 2015-07-24 16:56:20,015 o.d.tidy.merge.MergeExecutorService[188] - Job Success: datastar.117.6
DEBUG[main] 2015-07-24 16:56:20,015 o.d.tidy.merge.MergeExecutorService[262] - TotalToProcess = 14 totalCompleted 7 totalFailed 0 total Unrecoverable 0
DEBUG[main] 2015-07-24 16:56:20,015 o.d.tidy.merge.MergeExecutorService[178] - after submit 2
INFO [main] 2015-07-24 16:56:20,016 o.d.tidy.merge.MergeExecutorService[188] - Job Success: jgoldberg.4.1
DEBUG[main] 2015-07-24 16:56:20,016 o.d.tidy.merge.MergeExecutorService[262] - TotalToProcess = 14 totalCompleted 8 totalFailed 0 total Unrecoverable 0
DEBUG[main] 2015-07-24 16:56:20,016 o.d.tidy.merge.MergeExecutorService[178] - after submit 1
INFO [main] 2015-07-24 16:56:20,016 o.d.tidy.merge.MergeExecutorService[188] - Job Success: jimont.109.7
DEBUG[main] 2015-07-24 16:56:20,016 o.d.tidy.merge.MergeExecutorService[262] - TotalToProcess = 14 totalCompleted 9 totalFailed 0 total Unrecoverable 0
DEBUG[main] 2015-07-24 16:56:20,017 o.d.tidy.merge.MergeExecutorService[178] - after submit 0
INFO [main] 2015-07-24 16:56:20,017 o.d.tidy.merge.MergeExecutorService[188] - Job Success: BrianGratwicke.3.1
DEBUG[main] 2015-07-24 16:56:20,017 o.d.tidy.merge.MergeExecutorService[262] - TotalToProcess = 14 totalCompleted 10 totalFailed 0 total Unrecoverable 0
DEBUG[pool-8-thread-10] 2015-07-24 16:56:20,013 o.d.t.c.TidyJobThreadPoolExecutor[130] - job is of pid jimont.109.7
DEBUG[pool-8-thread-3] 2015-07-24 16:56:20,015 o.d.t.c.TidyJobThreadPoolExecutor[130] - job is of pid BrianGratwicke.3.1
DEBUG[pool-8-thread-1] 2015-07-24 16:56:20,489 o.d.t.c.TidyJobThreadPoolExecutor[130] - job is of pid jimont.128.4
DEBUG[main] 2015-07-24 16:56:20,489 o.d.tidy.merge.MergeExecutorService[178] - after submit 0
INFO [main] 2015-07-24 16:56:20,490 o.d.tidy.merge.MergeExecutorService[188] - Job Success: jimont.128.4
DEBUG[main] 2015-07-24 16:56:20,490 o.d.tidy.merge.MergeExecutorService[262] - TotalToProcess = 14 totalCompleted 11 totalFailed 0 total Unrecoverable 0
DEBUG[pool-8-thread-2] 2015-07-24 16:56:20,504 o.d.t.c.TidyJobThreadPoolExecutor[130] - job is of pid jimont.132.5
DEBUG[main] 2015-07-24 16:56:20,504 o.d.tidy.merge.MergeExecutorService[178] - after submit 0
INFO [main] 2015-07-24 16:56:20,504 o.d.tidy.merge.MergeExecutorService[188] - Job Success: jimont.132.5
DEBUG[main] 2015-07-24 16:56:20,505 o.d.tidy.merge.MergeExecutorService[262] - TotalToProcess = 14 totalCompleted 12 totalFailed 0 total Unrecoverable 0
DEBUG[pool-8-thread-5] 2015-07-24 16:56:20,512 o.d.t.c.TidyJobThreadPoolExecutor[130] - job is of pid kgordon.35.49
DEBUG[main] 2015-07-24 16:56:20,512 o.d.tidy.merge.MergeExecutorService[178] - after submit 0
DEBUG[pool-8-thread-4] 2015-07-24 16:56:20,513 o.d.t.c.TidyJobThreadPoolExecutor[130] - job is of pid resourceMap_evanlpettis.57.11
INFO [main] 2015-07-24 16:56:20,513 o.d.tidy.merge.MergeExecutorService[188] - Job Success: kgordon.35.49
DEBUG[main] 2015-07-24 16:56:20,513 o.d.tidy.merge.MergeExecutorService[262] - TotalToProcess = 14 totalCompleted 13 totalFailed 0 total Unrecoverable 0
DEBUG[main] 2015-07-24 16:56:20,513 o.d.tidy.merge.MergeExecutorService[178] - after submit 0
INFO [main] 2015-07-24 16:56:20,514 o.d.tidy.merge.MergeExecutorService[188] - Job Success: resourceMap_evanlpettis.57.11
DEBUG[main] 2015-07-24 16:56:20,514 o.d.tidy.merge.MergeExecutorService[262] - TotalToProcess = 14 totalCompleted 14 totalFailed 0 total Unrecoverable 0
INFO [main] 2015-07-24 16:56:20,514 o.d.tidy.merge.MergeExecutorService[282] - Number of Jobs Successfuly Completed 14
INFO [main] 2015-07-24 16:56:20,514 o.d.tidy.merge.MergeExecutorService[283] - Number of Jobs on Failed 0
INFO [main] 2015-07-24 16:56:20,515 o.d.tidy.merge.MergeExecutorService[284] - Number of Jobs with Unrecoverable Exceptions 0
DEBUG[main] 2015-07-24 16:56:20,539 o.d.t.merge.MergeExecutorServiceTest[89] - 14 14 0
Tests run: 6, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 8.892 sec
Running org.dataone.tidy.merge.MergeJobTest
INFO [main] 2015-07-24 16:56:20,550 org.dataone.tidy.merge.MergeJob[64] - Running MergeJob for foo
INFO [main] 2015-07-24 16:56:20,559 o.d.t.m.strategy.MergeSystemMetadata[125] - determined that urn:node:CNORC1 is ascendent from
INFO [main] 2015-07-24 16:56:20,559 o.d.t.m.strategy.MergeSystemMetadata[127] - urn:node:CNUNM1
INFO [main] 2015-07-24 16:56:20,560 o.d.t.m.strategy.MergeSystemMetadata[127] - urn:node:CNUCSB1
INFO [main] 2015-07-24 16:56:20,560 o.d.t.m.strategy.MergeSystemMetadata[127] - urn:node:CNORC1
DEBUG[main] 2015-07-24 16:56:20,562 o.d.t.m.strategy.MergeSystemMetadata[593] - newNodeList size: 3
DEBUG[main] 2015-07-24 16:56:20,562 o.d.t.m.strategy.MergeSystemMetadata[599] - blockList was modified
DEBUG[main] 2015-07-24 16:56:20,562 o.d.t.m.strategy.MergeSystemMetadata[604] - New Block list contains: blocked_MN_uno
DEBUG[main] 2015-07-24 16:56:20,562 o.d.t.m.strategy.MergeSystemMetadata[604] - New Block list contains: blocked_MN_tres
DEBUG[main] 2015-07-24 16:56:20,563 o.d.t.m.strategy.MergeSystemMetadata[604] - New Block list contains: blocked_MN_dos
DEBUG[main] 2015-07-24 16:56:20,607 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: //SystemMetadata
DEBUG[main] 2015-07-24 16:56:20,608 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AccessPolicy/tidy/MaxPermissionMap/user_1
DEBUG[main] 2015-07-24 16:56:20,608 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AccessPolicy/tidy/MaxPermissionMap/user_2
DEBUG[main] 2015-07-24 16:56:20,608 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AccessPolicy/tidy/MaxPermissionMap/user_3
DEBUG[main] 2015-07-24 16:56:20,609 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AccessPolicy/tidy/MaxPermissionMap/user_4
DEBUG[main] 2015-07-24 16:56:20,609 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AccessPolicy/tidy/MaxPermissionMap/user_5
DEBUG[main] 2015-07-24 16:56:20,609 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AccessPolicy/tidy/MaxPermissionMap/user_6
DEBUG[main] 2015-07-24 16:56:20,609 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Archived
DEBUG[main] 2015-07-24 16:56:20,610 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AuthoritativeMemberNode/Value
DEBUG[main] 2015-07-24 16:56:20,610 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Checksum/Algorithm
DEBUG[main] 2015-07-24 16:56:20,610 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Checksum/Value
DEBUG[main] 2015-07-24 16:56:20,610 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /DateSysMetadataModified
DEBUG[main] 2015-07-24 16:56:20,611 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /DateUploaded
DEBUG[main] 2015-07-24 16:56:20,611 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /FormatId/Value
DEBUG[main] 2015-07-24 16:56:20,611 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Identifier/Value
DEBUG[main] 2015-07-24 16:56:20,611 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ObsoletedBy
DEBUG[main] 2015-07-24 16:56:20,612 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ObsoletedBy/Value
DEBUG[main] 2015-07-24 16:56:20,612 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Obsoletes
DEBUG[main] 2015-07-24 16:56:20,612 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Obsoletes/Value
DEBUG[main] 2015-07-24 16:56:20,612 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /OriginMemberNode/Value
DEBUG[main] 2015-07-24 16:56:20,613 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicaList/tidy/FlattenedReplicas/0
DEBUG[main] 2015-07-24 16:56:20,613 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/BlockedMemberNodeList
DEBUG[main] 2015-07-24 16:56:20,613 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/BlockedMemberNodeList/0/Value
DEBUG[main] 2015-07-24 16:56:20,613 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/BlockedMemberNodeList/1/Value
DEBUG[main] 2015-07-24 16:56:20,614 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/BlockedMemberNodeList/2/Value
DEBUG[main] 2015-07-24 16:56:20,614 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/NumberReplicas
DEBUG[main] 2015-07-24 16:56:20,614 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList
DEBUG[main] 2015-07-24 16:56:20,614 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList/0/Value
DEBUG[main] 2015-07-24 16:56:20,614 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList/1/Value
DEBUG[main] 2015-07-24 16:56:20,615 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList/2/Value
DEBUG[main] 2015-07-24 16:56:20,615 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList/3/Value
DEBUG[main] 2015-07-24 16:56:20,615 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/ReplicationAllowed
DEBUG[main] 2015-07-24 16:56:20,615 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /RightsHolder/Value
DEBUG[main] 2015-07-24 16:56:20,616 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /SerialVersion
DEBUG[main] 2015-07-24 16:56:20,616 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Size
DEBUG[main] 2015-07-24 16:56:20,616 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Submitter/Value
INFO [main] 2015-07-24 16:56:20,616 org.dataone.tidy.merge.MergeJob[149] - *****Change Records [repo.Save in] (pid:foo): 21
ChangeRecord [id=null, pid=foo, runId=12, attribute=/AccessPolicy/tidy/MaxPermissionMap/user_1, authMN=null, changeRule=null, cnOrc=read, cnUcsb=write, cnUnm=read, resulting=null]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/AccessPolicy/tidy/MaxPermissionMap/user_2, authMN=null, changeRule=null, cnOrc=read, cnUcsb=null, cnUnm=read, resulting=null]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/AccessPolicy/tidy/MaxPermissionMap/user_3, authMN=null, changeRule=null, cnOrc=null, cnUcsb=null, cnUnm=write, resulting=null]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/AccessPolicy/tidy/MaxPermissionMap/user_4, authMN=write, changeRule=null, cnOrc=null, cnUcsb=null, cnUnm=null, resulting=write]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/AccessPolicy/tidy/MaxPermissionMap/user_5, authMN=write, changeRule=null, cnOrc=null, cnUcsb=null, cnUnm=null, resulting=write]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/AccessPolicy/tidy/MaxPermissionMap/user_6, authMN=read, changeRule=null, cnOrc=null, cnUcsb=null, cnUnm=null, resulting=read]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/DateSysMetadataModified, authMN=2006-05-04T00:00:12.000+00:00, changeRule=null, cnOrc=2006-05-04T00:00:11.000+00:00, cnUcsb=2006-05-04T00:00:13.000+00:00, cnUnm=2006-05-04T00:00:12.000+00:00, resulting=2006-05-04T00:00:13.000+00:00]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ObsoletedBy/Value, authMN=AFC12352, changeRule=null, cnOrc=null, cnUcsb=AFC12352, cnUnm=AFC12352, resulting=AFC12352]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/Obsoletes/Value, authMN=AFC123, changeRule=null, cnOrc=null, cnUcsb=AFC123, cnUnm=AFC123, resulting=AFC123]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicaList/tidy/FlattenedReplicas/0, authMN=urn:node:mn3 QUEUED 2006-05-04T18:13:51.000+00:00, changeRule=null, cnOrc=urn:node:mn3 QUEUED 2006-05-04T18:13:51.000+00:00, cnUcsb=urn:node:mn3 COMPLETED 2006-05-04T18:13:51.000+00:00, cnUnm=urn:node:mn3 QUEUED 2006-05-04T18:13:51.000+00:00, resulting=urn:node:mn3 COMPLETED 2006-05-04T18:13:51.000+00:00]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/BlockedMemberNodeList/0/Value, authMN=blocked_MN_dos, changeRule=null, cnOrc=null, cnUcsb=blocked_MN_dos, cnUnm=blocked_MN_dos, resulting=blocked_MN_dos]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/BlockedMemberNodeList/1/Value, authMN=blocked_MN_tres, changeRule=null, cnOrc=null, cnUcsb=blocked_MN_uno, cnUnm=blocked_MN_tres, resulting=blocked_MN_tres]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/BlockedMemberNodeList/2/Value, authMN=blocked_MN_uno, changeRule=null, cnOrc=null, cnUcsb=null, cnUnm=blocked_MN_uno, resulting=blocked_MN_uno]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/NumberReplicas, authMN=5, changeRule=null, cnOrc=null, cnUcsb=5, cnUnm=5, resulting=5]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/PreferredMemberNodeList/0/Value, authMN=pref_MN_four, changeRule=null, cnOrc=null, cnUcsb=pref_MN_four, cnUnm=pref_MN_four, resulting=pref_MN_four]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/PreferredMemberNodeList/1/Value, authMN=pref_MN_one, changeRule=null, cnOrc=null, cnUcsb=pref_MN_one, cnUnm=pref_MN_one, resulting=pref_MN_one]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/PreferredMemberNodeList/2/Value, authMN=pref_MN_three, changeRule=null, cnOrc=null, cnUcsb=pref_MN_two, cnUnm=pref_MN_three, resulting=pref_MN_three]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/PreferredMemberNodeList/3/Value, authMN=pref_MN_two, changeRule=null, cnOrc=null, cnUcsb=null, cnUnm=pref_MN_two, resulting=pref_MN_two]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/ReplicationAllowed, authMN=true, changeRule=null, cnOrc=false, cnUcsb=true, cnUnm=true, resulting=true]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/RightsHolder/Value, authMN=rh_1a, changeRule=null, cnOrc=rh_1c, cnUcsb=rh_1b, cnUnm=rh_1a, resulting=rh_1c]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/SerialVersion, authMN=4, changeRule=null, cnOrc=5, cnUcsb=4, cnUnm=4, resulting=5]
INFO [main] 2015-07-24 16:56:20,626 org.dataone.tidy.merge.MergeJob[152] - *****Change Records [repo.Save out] (pid:foo): null
MergeResult [id=null, pid=foo, mergeDate=07/24/2015:16:56:20:555, runId=12, status=SUCCESS, authMN=urn:node:mn1, exception='null']
MergeResult [id=null, pid=foo, mergeDate=07/24/2015:16:56:20:555, runId=12, status=SUCCESS, authMN=urn:node:mn1, exception='null']
<?xml version="1.0" encoding="UTF-8"?><d1:systemMetadata xmlns:d1="http://ns.dataone.org/service/types/v1"><serialVersion>4</serialVersion><identifier>ABC123</identifier><formatId>http://www.loc.gov/METS/</formatId><size>922337203</size><checksum algorithm="SHA-1">SGVsbG8gV29ybGQh</checksum><submitter>Robert P Waltz</submitter><rightsHolder>rh_1a</rightsHolder><accessPolicy><allow><subject>user_4</subject><subject>user_5</subject><permission>write</permission></allow><allow><subject>user_6</subject><permission>read</permission></allow></accessPolicy><replicationPolicy replicationAllowed="true" numberReplicas="5"><preferredMemberNode>pref_MN_one</preferredMemberNode><preferredMemberNode>pref_MN_two</preferredMemberNode><preferredMemberNode>pref_MN_three</preferredMemberNode><preferredMemberNode>pref_MN_four</preferredMemberNode><blockedMemberNode>blocked_MN_uno</blockedMemberNode><blockedMemberNode>blocked_MN_dos</blockedMemberNode><blockedMemberNode>blocked_MN_tres</blockedMemberNode></replicationPolicy><obsoletes>AFC123</obsoletes><obsoletedBy>AFC12352</obsoletedBy><dateUploaded>2006-05-01T00:00:00.000+00:00</dateUploaded><dateSysMetadataModified>2006-05-04T00:00:12.000+00:00</dateSysMetadataModified><originMemberNode>urn:node:mn1</originMemberNode><authoritativeMemberNode>urn:node:mn1</authoritativeMemberNode><replica><replicaMemberNode>urn:node:mn3</replicaMemberNode><replicationStatus>queued</replicationStatus><replicaVerified>2006-05-04T18:13:51.000+00:00</replicaVerified></replica></d1:systemMetadata>
INFO [main] 2015-07-24 16:56:20,632 org.dataone.tidy.merge.MergeJob[64] - Running MergeJob for foo
INFO [main] 2015-07-24 16:56:20,646 o.d.t.m.strategy.MergeSystemMetadata[125] - determined that urn:node:CNUNM1 is ascendent from
INFO [main] 2015-07-24 16:56:20,646 o.d.t.m.strategy.MergeSystemMetadata[127] - urn:node:CNUNM1
INFO [main] 2015-07-24 16:56:20,646 o.d.t.m.strategy.MergeSystemMetadata[127] - urn:node:CNUCSB1
DEBUG[main] 2015-07-24 16:56:20,728 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: //SystemMetadata
DEBUG[main] 2015-07-24 16:56:20,728 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AccessPolicy/tidy/MaxPermissionMap/cn=evos,o=NCEAS,dc=ecoinformatics,dc=org
DEBUG[main] 2015-07-24 16:56:20,735 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AccessPolicy/tidy/MaxPermissionMap/public
DEBUG[main] 2015-07-24 16:56:20,735 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Archived
DEBUG[main] 2015-07-24 16:56:20,736 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AuthoritativeMemberNode/Value
DEBUG[main] 2015-07-24 16:56:20,736 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Checksum/Algorithm
DEBUG[main] 2015-07-24 16:56:20,736 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Checksum/Value
DEBUG[main] 2015-07-24 16:56:20,736 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /DateSysMetadataModified
DEBUG[main] 2015-07-24 16:56:20,736 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /DateUploaded
DEBUG[main] 2015-07-24 16:56:20,737 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /FormatId/Value
DEBUG[main] 2015-07-24 16:56:20,737 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Identifier/Value
DEBUG[main] 2015-07-24 16:56:20,737 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ObsoletedBy
DEBUG[main] 2015-07-24 16:56:20,737 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Obsoletes/Value
DEBUG[main] 2015-07-24 16:56:20,738 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /OriginMemberNode/Value
DEBUG[main] 2015-07-24 16:56:20,738 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicaList/tidy/FlattenedReplicas/0
DEBUG[main] 2015-07-24 16:56:20,738 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicaList/tidy/FlattenedReplicas/1
DEBUG[main] 2015-07-24 16:56:20,738 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicaList/tidy/FlattenedReplicas/2
DEBUG[main] 2015-07-24 16:56:20,739 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/BlockedMemberNodeList
DEBUG[main] 2015-07-24 16:56:20,739 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/NumberReplicas
DEBUG[main] 2015-07-24 16:56:20,739 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList/0/Value
DEBUG[main] 2015-07-24 16:56:20,740 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList/1/Value
DEBUG[main] 2015-07-24 16:56:20,740 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/ReplicationAllowed
DEBUG[main] 2015-07-24 16:56:20,740 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /RightsHolder/Value
DEBUG[main] 2015-07-24 16:56:20,740 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /SerialVersion
DEBUG[main] 2015-07-24 16:56:20,741 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Size
DEBUG[main] 2015-07-24 16:56:20,741 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Submitter/Value
INFO [main] 2015-07-24 16:56:20,751 org.dataone.tidy.merge.MergeJob[149] - *****Change Records [repo.Save in] (pid:foo): 4
ChangeRecord [id=null, pid=foo, runId=12, attribute=//SystemMetadata, authMN=Present, changeRule=null, cnOrc=Not Available, cnUcsb=Present, cnUnm=Present, resulting=Present]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/AccessPolicy/tidy/MaxPermissionMap/public, authMN=read, changeRule=null, cnOrc=null, cnUcsb=null, cnUnm=read, resulting=read]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicaList/tidy/FlattenedReplicas/1, authMN=urn:node:KNB COMPLETED 2013-12-09T23:22:51.946+00:00, changeRule=null, cnOrc=null, cnUcsb=urn:node:KNB COMPLETED 2013-12-09T23:22:51.946+00:00, cnUnm=urn:node:KNB COMPLETED 2010-12-09T11:00:00.000+00:00, resulting=urn:node:KNB COMPLETED 2013-12-09T23:22:51.946+00:00]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicaList/tidy/FlattenedReplicas/2, authMN=urn:node:mnUNM1 COMPLETED 2013-12-09T23:22:54.801+00:00, changeRule=null, cnOrc=null, cnUcsb=urn:node:mnUNM1 COMPLETED 2013-12-09T23:22:54.801+00:00, cnUnm=null, resulting=urn:node:mnUNM1 COMPLETED 2013-12-09T23:22:54.801+00:00]
INFO [main] 2015-07-24 16:56:20,752 org.dataone.tidy.merge.MergeJob[152] - *****Change Records [repo.Save out] (pid:foo): null
MergeResult [id=null, pid=foo, mergeDate=07/24/2015:16:56:20:643, runId=12, status=SUCCESS, authMN=urn:node:GOA, exception='null']
MergeResult [id=null, pid=foo, mergeDate=07/24/2015:16:56:20:643, runId=12, status=SUCCESS, authMN=urn:node:GOA, exception='null']
<?xml version="1.0" encoding="UTF-8"?><d1:systemMetadata xmlns:d1="http://ns.dataone.org/service/types/v1"><serialVersion>7</serialVersion><identifier>df35d.21.2</identifier><formatId>text/csv</formatId><size>3349</size><checksum algorithm="MD5">d88b0426d2e92d29b4132398740f8e22
</checksum><submitter>uid=sclark,o=NCEAS,dc=ecoinformatics,dc=org</submitter><rightsHolder>uid=sclark,o=NCEAS,dc=ecoinformatics,dc=org
</rightsHolder><accessPolicy><allow><subject>public</subject><permission>read</permission></allow><allow><subject>cn=evos,o=NCEAS,dc=ecoinformatics,dc=org</subject><permission>read</permission><permission>write</permission><permission>changePermission</permission></allow></accessPolicy><replicationPolicy replicationAllowed="true" numberReplicas="2"><preferredMemberNode>urn:node:KNB</preferredMemberNode><preferredMemberNode>urn:node:mnUNM1</preferredMemberNode></replicationPolicy><obsoletes>df35d.21.1</obsoletes><archived>false</archived><dateUploaded>2013-01-03T00:00:00.000+00:00</dateUploaded><dateSysMetadataModified>2013-12-09T23:23:19.692+00:00</dateSysMetadataModified><originMemberNode>urn:node:GOA</originMemberNode><authoritativeMemberNode>urn:node:GOA</authoritativeMemberNode><replica><replicaMemberNode>urn:node:GOA</replicaMemberNode><replicationStatus>completed</replicationStatus><replicaVerified>2013-12-09T23:18:17.172+00:00</replicaVerified></replica><replica><replicaMemberNode>urn:node:KNB</replicaMemberNode><replicationStatus>completed</replicationStatus><replicaVerified>2013-12-09T23:22:51.946+00:00</replicaVerified></replica><replica><replicaMemberNode>urn:node:mnUNM1</replicaMemberNode><replicationStatus>completed</replicationStatus><replicaVerified>2013-12-09T23:22:54.801+00:00</replicaVerified></replica></d1:systemMetadata>
INFO [main] 2015-07-24 16:56:20,756 org.dataone.tidy.merge.MergeJob[64] - Running MergeJob for foo
INFO [main] 2015-07-24 16:56:20,769 o.d.t.m.strategy.MergeSystemMetadata[125] - determined that urn:node:CNUNM1 is ascendent from
INFO [main] 2015-07-24 16:56:20,770 o.d.t.m.strategy.MergeSystemMetadata[127] - urn:node:CNUNM1
INFO [main] 2015-07-24 16:56:20,770 o.d.t.m.strategy.MergeSystemMetadata[127] - urn:node:CNUCSB1
INFO [main] 2015-07-24 16:56:20,770 o.d.t.m.strategy.MergeSystemMetadata[127] - urn:node:CNORC1
DEBUG[main] 2015-07-24 16:56:20,848 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: //SystemMetadata
DEBUG[main] 2015-07-24 16:56:20,848 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AccessPolicy/tidy/MaxPermissionMap/public
DEBUG[main] 2015-07-24 16:56:20,848 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Archived
DEBUG[main] 2015-07-24 16:56:20,848 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AuthoritativeMemberNode/Value
DEBUG[main] 2015-07-24 16:56:20,849 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Checksum/Algorithm
DEBUG[main] 2015-07-24 16:56:20,855 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Checksum/Value
DEBUG[main] 2015-07-24 16:56:20,855 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /DateSysMetadataModified
DEBUG[main] 2015-07-24 16:56:20,855 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /DateUploaded
DEBUG[main] 2015-07-24 16:56:20,856 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /FormatId/Value
DEBUG[main] 2015-07-24 16:56:20,856 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Identifier/Value
DEBUG[main] 2015-07-24 16:56:20,856 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ObsoletedBy
DEBUG[main] 2015-07-24 16:56:20,856 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Obsoletes
DEBUG[main] 2015-07-24 16:56:20,857 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /OriginMemberNode/Value
DEBUG[main] 2015-07-24 16:56:20,857 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicaList/tidy/FlattenedReplicas/0
DEBUG[main] 2015-07-24 16:56:20,857 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicaList/tidy/FlattenedReplicas/1
DEBUG[main] 2015-07-24 16:56:20,857 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicaList/tidy/FlattenedReplicas/2
DEBUG[main] 2015-07-24 16:56:20,858 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicaList/tidy/FlattenedReplicas/3
DEBUG[main] 2015-07-24 16:56:20,858 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicaList/tidy/FlattenedReplicas/4
DEBUG[main] 2015-07-24 16:56:20,858 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/BlockedMemberNodeList
DEBUG[main] 2015-07-24 16:56:20,858 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/NumberReplicas
DEBUG[main] 2015-07-24 16:56:20,859 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList
DEBUG[main] 2015-07-24 16:56:20,859 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/ReplicationAllowed
DEBUG[main] 2015-07-24 16:56:20,859 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /RightsHolder/Value
DEBUG[main] 2015-07-24 16:56:20,859 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /SerialVersion
DEBUG[main] 2015-07-24 16:56:20,860 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Size
DEBUG[main] 2015-07-24 16:56:20,860 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Submitter/Value
INFO [main] 2015-07-24 16:56:20,860 org.dataone.tidy.merge.MergeJob[149] - *****Change Records [repo.Save in] (pid:foo): 0
INFO [main] 2015-07-24 16:56:20,860 org.dataone.tidy.merge.MergeJob[152] - *****Change Records [repo.Save out] (pid:foo): null
MergeResult [id=null, pid=foo, mergeDate=07/24/2015:16:56:20:756, runId=12, status=SUCCESS, authMN=urn:node:mnDemo6, exception='null']
MergeResult [id=null, pid=foo, mergeDate=07/24/2015:16:56:20:756, runId=12, status=SUCCESS, authMN=urn:node:mnDemo6, exception='null']
<?xml version="1.0" encoding="UTF-8"?><d1:systemMetadata xmlns:d1="http://ns.dataone.org/service/types/v1"><serialVersion>1891</serialVersion><identifier>EVAWF1Metadata20</identifier><formatId>FGDC-STD-001-1998</formatId><size>4965</size><checksum algorithm="SHA-1">7341095a94fa2712ad75ecc30ef6a9fc805dafe1</checksum><submitter>CN=Victor Cuevas A1759,O=Google,C=US,DC=cilogon,DC=org</submitter><rightsHolder>CN=VCV,DC=dataone,DC=org</rightsHolder><accessPolicy><allow><subject>public</subject><permission>read</permission></allow></accessPolicy><replicationPolicy replicationAllowed="true" numberReplicas="3"/><archived>false</archived><dateUploaded>2013-02-17T03:07:45.504+00:00</dateUploaded><dateSysMetadataModified>2013-11-26T17:29:56.459+00:00</dateSysMetadataModified><originMemberNode>urn:node:mnDemo6</originMemberNode><authoritativeMemberNode>urn:node:mnDemo6</authoritativeMemberNode><replica><replicaMemberNode>urn:node:mnDemo6</replicaMemberNode><replicationStatus>completed</replicationStatus><replicaVerified>2013-11-20T20:57:38.695+00:00</replicaVerified></replica><replica><replicaMemberNode>urn:node:cnDev</replicaMemberNode><replicationStatus>completed</replicationStatus><replicaVerified>2013-11-20T20:57:38.824+00:00</replicaVerified></replica><replica><replicaMemberNode>urn:node:mnDemo7</replicaMemberNode><replicationStatus>completed</replicationStatus><replicaVerified>2013-11-20T20:57:57.537+00:00</replicaVerified></replica><replica><replicaMemberNode>urn:node:mnDemo8</replicaMemberNode><replicationStatus>completed</replicationStatus><replicaVerified>2013-11-20T20:57:58.526+00:00</replicaVerified></replica><replica><replicaMemberNode>urn:node:mnDemo5</replicaMemberNode><replicationStatus>completed</replicationStatus><replicaVerified>2013-11-26T17:28:45.695+00:00</replicaVerified></replica></d1:systemMetadata>
INFO [main] 2015-07-24 16:56:20,873 org.dataone.tidy.merge.MergeJob[64] - Running MergeJob for foo
INFO [main] 2015-07-24 16:56:20,877 o.d.t.m.strategy.MergeSystemMetadata[125] - determined that urn:node:cnORC is ascendent from
INFO [main] 2015-07-24 16:56:20,887 o.d.t.m.strategy.MergeSystemMetadata[127] - urn:node:cnORC
INFO [main] 2015-07-24 16:56:20,887 o.d.t.m.strategy.MergeSystemMetadata[127] - urn:node:cnUNM
INFO [main] 2015-07-24 16:56:20,887 o.d.t.m.strategy.MergeSystemMetadata[127] - urn:node:cnUCSB
DEBUG[main] 2015-07-24 16:56:20,889 o.d.t.m.strategy.MergeSystemMetadata[593] - newNodeList size: 3
DEBUG[main] 2015-07-24 16:56:20,890 o.d.t.m.strategy.MergeSystemMetadata[599] - blockList was modified
DEBUG[main] 2015-07-24 16:56:20,890 o.d.t.m.strategy.MergeSystemMetadata[604] - New Block list contains: blocked_MN_uno
DEBUG[main] 2015-07-24 16:56:20,890 o.d.t.m.strategy.MergeSystemMetadata[604] - New Block list contains: blocked_MN_tres
DEBUG[main] 2015-07-24 16:56:20,890 o.d.t.m.strategy.MergeSystemMetadata[604] - New Block list contains: blocked_MN_dos
DEBUG[main] 2015-07-24 16:56:20,923 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: //SystemMetadata
DEBUG[main] 2015-07-24 16:56:20,924 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AccessPolicy/tidy/MaxPermissionMap/user_4
DEBUG[main] 2015-07-24 16:56:20,924 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AccessPolicy/tidy/MaxPermissionMap/user_5
DEBUG[main] 2015-07-24 16:56:20,924 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AccessPolicy/tidy/MaxPermissionMap/user_6
DEBUG[main] 2015-07-24 16:56:20,925 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Archived
DEBUG[main] 2015-07-24 16:56:20,925 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AuthoritativeMemberNode/Value
DEBUG[main] 2015-07-24 16:56:20,931 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Checksum/Algorithm
DEBUG[main] 2015-07-24 16:56:20,931 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Checksum/Value
DEBUG[main] 2015-07-24 16:56:20,931 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /DateSysMetadataModified
DEBUG[main] 2015-07-24 16:56:20,932 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /DateUploaded
DEBUG[main] 2015-07-24 16:56:20,932 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /FormatId/Value
DEBUG[main] 2015-07-24 16:56:20,932 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Identifier/Value
DEBUG[main] 2015-07-24 16:56:20,932 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ObsoletedBy/Value
DEBUG[main] 2015-07-24 16:56:20,933 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Obsoletes/Value
DEBUG[main] 2015-07-24 16:56:20,933 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /OriginMemberNode/Value
DEBUG[main] 2015-07-24 16:56:20,933 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicaList/tidy/FlattenedReplicas/0
DEBUG[main] 2015-07-24 16:56:20,933 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/BlockedMemberNodeList/0/Value
DEBUG[main] 2015-07-24 16:56:20,933 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/BlockedMemberNodeList/1/Value
DEBUG[main] 2015-07-24 16:56:20,934 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/BlockedMemberNodeList/2/Value
DEBUG[main] 2015-07-24 16:56:20,934 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/NumberReplicas
DEBUG[main] 2015-07-24 16:56:20,934 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList/0/Value
DEBUG[main] 2015-07-24 16:56:20,934 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList/1/Value
DEBUG[main] 2015-07-24 16:56:20,935 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList/2/Value
DEBUG[main] 2015-07-24 16:56:20,935 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList/3/Value
DEBUG[main] 2015-07-24 16:56:20,935 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/ReplicationAllowed
DEBUG[main] 2015-07-24 16:56:20,935 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /RightsHolder/Value
DEBUG[main] 2015-07-24 16:56:20,936 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /SerialVersion
DEBUG[main] 2015-07-24 16:56:20,943 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Size
DEBUG[main] 2015-07-24 16:56:20,943 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Submitter/Value
INFO [main] 2015-07-24 16:56:20,943 org.dataone.tidy.merge.MergeJob[149] - *****Change Records [repo.Save in] (pid:foo): 1
ChangeRecord [id=null, pid=foo, runId=12, attribute=//SystemMetadata, authMN=Present, changeRule=null, cnOrc=Not Available, cnUcsb=Not Available, cnUnm=Not Available, resulting=Present]
INFO [main] 2015-07-24 16:56:20,944 org.dataone.tidy.merge.MergeJob[152] - *****Change Records [repo.Save out] (pid:foo): null
org.dataone.cn.dao.exceptions.DataAccessException: java.lang.Exception: a test fail at save-time
at org.dataone.tidy.merge.MockFailSaveSystemMetadataTidyDaoImpl.saveSystemMetadata(MockFailSaveSystemMetadataTidyDaoImpl.java:65)
at org.dataone.tidy.merge.MergeJob.persistMergeReport(MergeJob.java:156)
at org.dataone.tidy.merge.MergeJob.call(MergeJob.java:101)
at org.dataone.tidy.merge.MergeJobTest.testCall_CaughtException(MergeJobTest.java:158)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:45)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:42)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:263)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:68)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:47)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:60)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:229)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:50)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222)
at org.junit.runners.ParentRunner.run(ParentRunner.java:300)
at org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:53)
at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:123)
at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:104)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.apache.maven.surefire.util.ReflectionUtils.invokeMethodWithArray(ReflectionUtils.java:164)
at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:110)
at org.apache.maven.surefire.booter.SurefireStarter.invokeProvider(SurefireStarter.java:175)
at org.apache.maven.surefire.booter.SurefireStarter.runSuitesInProcessWhenForked(SurefireStarter.java:107)
at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:68)
Caused by: java.lang.Exception: a test fail at save-time
at org.dataone.tidy.merge.MockFailSaveSystemMetadataTidyDaoImpl.saveSystemMetadata(MockFailSaveSystemMetadataTidyDaoImpl.java:64)
... 33 more
MergeResult [id=null, pid=foo, mergeDate=07/24/2015:16:56:20:873, runId=12, status=FAILURE, authMN=urn:node:mn1, exception='org.dataone.cn.dao.exceptions.DataAccessException: java.lang.Exception: a test fail at save-time: MockFailSaveSystemMetadataTidyDaoImpl.java:65']
MergeResult [id=null, pid=foo, mergeDate=07/24/2015:16:56:20:873, runId=12, status=FAILURE, authMN=urn:node:mn1, exception='org.dataone.cn.dao.exceptions.DataAccessException: java.lang.Exception: a test fail at save-time: MockFailSaveSystemMetadataTidyDaoImpl.java:65']
<?xml version="1.0" encoding="UTF-8"?><d1:systemMetadata xmlns:d1="http://ns.dataone.org/service/types/v1"><serialVersion>4</serialVersion><identifier>ABC123</identifier><formatId>http://www.loc.gov/METS/</formatId><size>922337203</size><checksum algorithm="SHA-1">SGVsbG8gV29ybGQh</checksum><submitter>Robert P Waltz</submitter><rightsHolder>rh_1a</rightsHolder><accessPolicy><allow><subject>user_4</subject><subject>user_5</subject><permission>write</permission></allow><allow><subject>user_6</subject><permission>read</permission></allow></accessPolicy><replicationPolicy replicationAllowed="true" numberReplicas="5"><preferredMemberNode>pref_MN_one</preferredMemberNode><preferredMemberNode>pref_MN_two</preferredMemberNode><preferredMemberNode>pref_MN_three</preferredMemberNode><preferredMemberNode>pref_MN_four</preferredMemberNode><blockedMemberNode>blocked_MN_uno</blockedMemberNode><blockedMemberNode>blocked_MN_dos</blockedMemberNode><blockedMemberNode>blocked_MN_tres</blockedMemberNode></replicationPolicy><obsoletes>AFC123</obsoletes><obsoletedBy>AFC12352</obsoletedBy><dateUploaded>2006-05-01T00:00:00.000+00:00</dateUploaded><dateSysMetadataModified>2006-05-04T00:00:12.000+00:00</dateSysMetadataModified><originMemberNode>urn:node:mn1</originMemberNode><authoritativeMemberNode>urn:node:mn1</authoritativeMemberNode><replica><replicaMemberNode>urn:node:mn3</replicaMemberNode><replicationStatus>queued</replicationStatus><replicaVerified>2006-05-04T18:13:51.000+00:00</replicaVerified></replica></d1:systemMetadata>
INFO [main] 2015-07-24 16:56:20,973 org.dataone.tidy.merge.MergeJob[64] - Running MergeJob for foo
INFO [main] 2015-07-24 16:56:20,977 o.d.t.m.strategy.MergeSystemMetadata[125] - determined that urn:node:CNORC1 is ascendent from
INFO [main] 2015-07-24 16:56:20,978 o.d.t.m.strategy.MergeSystemMetadata[127] - urn:node:CNUNM1
INFO [main] 2015-07-24 16:56:20,978 o.d.t.m.strategy.MergeSystemMetadata[127] - urn:node:CNUCSB1
INFO [main] 2015-07-24 16:56:20,978 o.d.t.m.strategy.MergeSystemMetadata[127] - urn:node:CNORC1
DEBUG[main] 2015-07-24 16:56:20,980 o.d.t.m.strategy.MergeSystemMetadata[593] - newNodeList size: 3
DEBUG[main] 2015-07-24 16:56:20,980 o.d.t.m.strategy.MergeSystemMetadata[599] - blockList was modified
DEBUG[main] 2015-07-24 16:56:20,987 o.d.t.m.strategy.MergeSystemMetadata[604] - New Block list contains: blocked_MN_uno
DEBUG[main] 2015-07-24 16:56:20,987 o.d.t.m.strategy.MergeSystemMetadata[604] - New Block list contains: blocked_MN_tres
DEBUG[main] 2015-07-24 16:56:20,987 o.d.t.m.strategy.MergeSystemMetadata[604] - New Block list contains: blocked_MN_dos
DEBUG[main] 2015-07-24 16:56:21,036 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: //SystemMetadata
DEBUG[main] 2015-07-24 16:56:21,037 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AccessPolicy/tidy/MaxPermissionMap/user_1
DEBUG[main] 2015-07-24 16:56:21,037 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AccessPolicy/tidy/MaxPermissionMap/user_2
DEBUG[main] 2015-07-24 16:56:21,037 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AccessPolicy/tidy/MaxPermissionMap/user_3
DEBUG[main] 2015-07-24 16:56:21,037 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AccessPolicy/tidy/MaxPermissionMap/user_4
DEBUG[main] 2015-07-24 16:56:21,038 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AccessPolicy/tidy/MaxPermissionMap/user_5
DEBUG[main] 2015-07-24 16:56:21,038 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AccessPolicy/tidy/MaxPermissionMap/user_6
DEBUG[main] 2015-07-24 16:56:21,038 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Archived
DEBUG[main] 2015-07-24 16:56:21,038 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AuthoritativeMemberNode/Value
DEBUG[main] 2015-07-24 16:56:21,038 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Checksum/Algorithm
DEBUG[main] 2015-07-24 16:56:21,039 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Checksum/Value
DEBUG[main] 2015-07-24 16:56:21,039 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /DateSysMetadataModified
DEBUG[main] 2015-07-24 16:56:21,039 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /DateUploaded
DEBUG[main] 2015-07-24 16:56:21,039 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /FormatId/Value
DEBUG[main] 2015-07-24 16:56:21,040 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Identifier/Value
DEBUG[main] 2015-07-24 16:56:21,040 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ObsoletedBy
DEBUG[main] 2015-07-24 16:56:21,040 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ObsoletedBy/Value
DEBUG[main] 2015-07-24 16:56:21,040 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Obsoletes
DEBUG[main] 2015-07-24 16:56:21,041 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Obsoletes/Value
DEBUG[main] 2015-07-24 16:56:21,041 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /OriginMemberNode/Value
DEBUG[main] 2015-07-24 16:56:21,041 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicaList/tidy/FlattenedReplicas/0
DEBUG[main] 2015-07-24 16:56:21,041 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/BlockedMemberNodeList
DEBUG[main] 2015-07-24 16:56:21,041 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/BlockedMemberNodeList/0/Value
DEBUG[main] 2015-07-24 16:56:21,042 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/BlockedMemberNodeList/1/Value
DEBUG[main] 2015-07-24 16:56:21,042 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/BlockedMemberNodeList/2/Value
DEBUG[main] 2015-07-24 16:56:21,042 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/NumberReplicas
DEBUG[main] 2015-07-24 16:56:21,042 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList
DEBUG[main] 2015-07-24 16:56:21,043 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList/0/Value
DEBUG[main] 2015-07-24 16:56:21,043 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList/1/Value
DEBUG[main] 2015-07-24 16:56:21,051 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList/2/Value
DEBUG[main] 2015-07-24 16:56:21,051 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList/3/Value
DEBUG[main] 2015-07-24 16:56:21,052 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/ReplicationAllowed
DEBUG[main] 2015-07-24 16:56:21,052 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /RightsHolder/Value
DEBUG[main] 2015-07-24 16:56:21,052 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /SerialVersion
DEBUG[main] 2015-07-24 16:56:21,052 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Size
DEBUG[main] 2015-07-24 16:56:21,053 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Submitter/Value
INFO [main] 2015-07-24 16:56:21,053 org.dataone.tidy.merge.MergeJob[149] - *****Change Records [repo.Save in] (pid:foo): 21
ChangeRecord [id=null, pid=foo, runId=12, attribute=/AccessPolicy/tidy/MaxPermissionMap/user_1, authMN=null, changeRule=null, cnOrc=read, cnUcsb=write, cnUnm=read, resulting=null]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/AccessPolicy/tidy/MaxPermissionMap/user_2, authMN=null, changeRule=null, cnOrc=read, cnUcsb=null, cnUnm=read, resulting=null]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/AccessPolicy/tidy/MaxPermissionMap/user_3, authMN=null, changeRule=null, cnOrc=null, cnUcsb=null, cnUnm=write, resulting=null]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/AccessPolicy/tidy/MaxPermissionMap/user_4, authMN=write, changeRule=null, cnOrc=null, cnUcsb=null, cnUnm=null, resulting=write]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/AccessPolicy/tidy/MaxPermissionMap/user_5, authMN=write, changeRule=null, cnOrc=null, cnUcsb=null, cnUnm=null, resulting=write]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/AccessPolicy/tidy/MaxPermissionMap/user_6, authMN=read, changeRule=null, cnOrc=null, cnUcsb=null, cnUnm=null, resulting=read]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/DateSysMetadataModified, authMN=2006-05-04T00:00:12.000+00:00, changeRule=null, cnOrc=2006-05-04T00:00:11.000+00:00, cnUcsb=2006-05-04T00:00:13.000+00:00, cnUnm=2006-05-04T00:00:12.000+00:00, resulting=2006-05-04T00:00:13.000+00:00]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ObsoletedBy/Value, authMN=AFC12352, changeRule=null, cnOrc=null, cnUcsb=AFC12352, cnUnm=AFC12352, resulting=AFC12352]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/Obsoletes/Value, authMN=AFC123, changeRule=null, cnOrc=null, cnUcsb=AFC123, cnUnm=AFC123, resulting=AFC123]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicaList/tidy/FlattenedReplicas/0, authMN=urn:node:mn3 QUEUED 2006-05-04T18:13:51.000+00:00, changeRule=null, cnOrc=urn:node:mn3 QUEUED 2006-05-04T18:13:51.000+00:00, cnUcsb=urn:node:mn3 COMPLETED 2006-05-04T18:13:51.000+00:00, cnUnm=urn:node:mn3 QUEUED 2006-05-04T18:13:51.000+00:00, resulting=urn:node:mn3 COMPLETED 2006-05-04T18:13:51.000+00:00]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/BlockedMemberNodeList/0/Value, authMN=blocked_MN_dos, changeRule=null, cnOrc=null, cnUcsb=blocked_MN_dos, cnUnm=blocked_MN_dos, resulting=blocked_MN_dos]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/BlockedMemberNodeList/1/Value, authMN=blocked_MN_tres, changeRule=null, cnOrc=null, cnUcsb=blocked_MN_uno, cnUnm=blocked_MN_tres, resulting=blocked_MN_tres]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/BlockedMemberNodeList/2/Value, authMN=blocked_MN_uno, changeRule=null, cnOrc=null, cnUcsb=null, cnUnm=blocked_MN_uno, resulting=blocked_MN_uno]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/NumberReplicas, authMN=5, changeRule=null, cnOrc=null, cnUcsb=5, cnUnm=5, resulting=5]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/PreferredMemberNodeList/0/Value, authMN=pref_MN_four, changeRule=null, cnOrc=null, cnUcsb=pref_MN_four, cnUnm=pref_MN_four, resulting=pref_MN_four]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/PreferredMemberNodeList/1/Value, authMN=pref_MN_one, changeRule=null, cnOrc=null, cnUcsb=pref_MN_one, cnUnm=pref_MN_one, resulting=pref_MN_one]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/PreferredMemberNodeList/2/Value, authMN=pref_MN_three, changeRule=null, cnOrc=null, cnUcsb=pref_MN_two, cnUnm=pref_MN_three, resulting=pref_MN_three]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/PreferredMemberNodeList/3/Value, authMN=pref_MN_two, changeRule=null, cnOrc=null, cnUcsb=null, cnUnm=pref_MN_two, resulting=pref_MN_two]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/ReplicationAllowed, authMN=true, changeRule=null, cnOrc=false, cnUcsb=true, cnUnm=true, resulting=true]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/RightsHolder/Value, authMN=rh_1a, changeRule=null, cnOrc=rh_1c, cnUcsb=rh_1b, cnUnm=rh_1a, resulting=rh_1c]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/SerialVersion, authMN=4, changeRule=null, cnOrc=5, cnUcsb=4, cnUnm=4, resulting=5]
INFO [main] 2015-07-24 16:56:21,056 org.dataone.tidy.merge.MergeJob[152] - *****Change Records [repo.Save out] (pid:foo): null
ERROR[main] 2015-07-24 16:56:21,072 org.dataone.tidy.merge.MergeJob[103] - null
java.lang.NullPointerException: null
at org.springframework.jdbc.UncategorizedSQLException.<init>(UncategorizedSQLException.java:44) ~[spring-jdbc-3.1.1.RELEASE.jar:3.1.1.RELEASE]
at org.dataone.tidy.merge.MockFailedMergeResultRepository.save(MockFailedMergeResultRepository.java:82) ~[test-classes/:na]
at org.dataone.tidy.merge.MockFailedMergeResultRepository.save(MockFailedMergeResultRepository.java:12) ~[test-classes/:na]
at org.dataone.tidy.merge.MergeJob.persistMergeReport(MergeJob.java:172) ~[classes/:na]
at org.dataone.tidy.merge.MergeJob.call(MergeJob.java:101) ~[classes/:na]
at org.dataone.tidy.merge.MergeJobTest.testCall_PersistMergeResultException(MergeJobTest.java:242) [test-classes/:na]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_79]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_79]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_79]
at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_79]
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:45) [junit-4.10.jar:na]
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15) [junit-4.10.jar:na]
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:42) [junit-4.10.jar:na]
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20) [junit-4.10.jar:na]
at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28) [junit-4.10.jar:na]
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:263) [junit-4.10.jar:na]
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:68) [junit-4.10.jar:na]
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:47) [junit-4.10.jar:na]
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231) [junit-4.10.jar:na]
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:60) [junit-4.10.jar:na]
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:229) [junit-4.10.jar:na]
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:50) [junit-4.10.jar:na]
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222) [junit-4.10.jar:na]
at org.junit.runners.ParentRunner.run(ParentRunner.java:300) [junit-4.10.jar:na]
at org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:53) [surefire-junit4-2.10.jar:2.10]
at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:123) [surefire-junit4-2.10.jar:2.10]
at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:104) [surefire-junit4-2.10.jar:2.10]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_79]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_79]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_79]
at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_79]
at org.apache.maven.surefire.util.ReflectionUtils.invokeMethodWithArray(ReflectionUtils.java:164) [surefire-api-2.10.jar:2.10]
at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:110) [surefire-booter-2.10.jar:2.10]
at org.apache.maven.surefire.booter.SurefireStarter.invokeProvider(SurefireStarter.java:175) [surefire-booter-2.10.jar:2.10]
at org.apache.maven.surefire.booter.SurefireStarter.runSuitesInProcessWhenForked(SurefireStarter.java:107) [surefire-booter-2.10.jar:2.10]
at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:68) [surefire-booter-2.10.jar:2.10]
org.dataone.tidy.merge.MockChangeRecordRepository@3cc5a37d
[ChangeRecord [id=null, pid=foo, runId=12, attribute=/AccessPolicy/tidy/MaxPermissionMap/user_1, authMN=null, changeRule=null, cnOrc=read, cnUcsb=write, cnUnm=read, resulting=null], ChangeRecord [id=null, pid=foo, runId=12, attribute=/AccessPolicy/tidy/MaxPermissionMap/user_2, authMN=null, changeRule=null, cnOrc=read, cnUcsb=null, cnUnm=read, resulting=null], ChangeRecord [id=null, pid=foo, runId=12, attribute=/AccessPolicy/tidy/MaxPermissionMap/user_3, authMN=null, changeRule=null, cnOrc=null, cnUcsb=null, cnUnm=write, resulting=null], ChangeRecord [id=null, pid=foo, runId=12, attribute=/AccessPolicy/tidy/MaxPermissionMap/user_4, authMN=write, changeRule=null, cnOrc=null, cnUcsb=null, cnUnm=null, resulting=write], ChangeRecord [id=null, pid=foo, runId=12, attribute=/AccessPolicy/tidy/MaxPermissionMap/user_5, authMN=write, changeRule=null, cnOrc=null, cnUcsb=null, cnUnm=null, resulting=write], ChangeRecord [id=null, pid=foo, runId=12, attribute=/AccessPolicy/tidy/MaxPermissionMap/user_6, authMN=read, changeRule=null, cnOrc=null, cnUcsb=null, cnUnm=null, resulting=read], ChangeRecord [id=null, pid=foo, runId=12, attribute=/DateSysMetadataModified, authMN=2006-05-04T00:00:12.000+00:00, changeRule=null, cnOrc=2006-05-04T00:00:11.000+00:00, cnUcsb=2006-05-04T00:00:13.000+00:00, cnUnm=2006-05-04T00:00:12.000+00:00, resulting=2006-05-04T00:00:13.000+00:00], ChangeRecord [id=null, pid=foo, runId=12, attribute=/ObsoletedBy/Value, authMN=AFC12352, changeRule=null, cnOrc=null, cnUcsb=AFC12352, cnUnm=AFC12352, resulting=AFC12352], ChangeRecord [id=null, pid=foo, runId=12, attribute=/Obsoletes/Value, authMN=AFC123, changeRule=null, cnOrc=null, cnUcsb=AFC123, cnUnm=AFC123, resulting=AFC123], ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicaList/tidy/FlattenedReplicas/0, authMN=urn:node:mn3 QUEUED 2006-05-04T18:13:51.000+00:00, changeRule=null, cnOrc=urn:node:mn3 QUEUED 2006-05-04T18:13:51.000+00:00, cnUcsb=urn:node:mn3 COMPLETED 2006-05-04T18:13:51.000+00:00, cnUnm=urn:node:mn3 QUEUED 2006-05-04T18:13:51.000+00:00, resulting=urn:node:mn3 COMPLETED 2006-05-04T18:13:51.000+00:00], ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/BlockedMemberNodeList/0/Value, authMN=blocked_MN_dos, changeRule=null, cnOrc=null, cnUcsb=blocked_MN_dos, cnUnm=blocked_MN_dos, resulting=blocked_MN_dos], ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/BlockedMemberNodeList/1/Value, authMN=blocked_MN_tres, changeRule=null, cnOrc=null, cnUcsb=blocked_MN_uno, cnUnm=blocked_MN_tres, resulting=blocked_MN_tres], ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/BlockedMemberNodeList/2/Value, authMN=blocked_MN_uno, changeRule=null, cnOrc=null, cnUcsb=null, cnUnm=blocked_MN_uno, resulting=blocked_MN_uno], ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/NumberReplicas, authMN=5, changeRule=null, cnOrc=null, cnUcsb=5, cnUnm=5, resulting=5], ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/PreferredMemberNodeList/0/Value, authMN=pref_MN_four, changeRule=null, cnOrc=null, cnUcsb=pref_MN_four, cnUnm=pref_MN_four, resulting=pref_MN_four], ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/PreferredMemberNodeList/1/Value, authMN=pref_MN_one, changeRule=null, cnOrc=null, cnUcsb=pref_MN_one, cnUnm=pref_MN_one, resulting=pref_MN_one], ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/PreferredMemberNodeList/2/Value, authMN=pref_MN_three, changeRule=null, cnOrc=null, cnUcsb=pref_MN_two, cnUnm=pref_MN_three, resulting=pref_MN_three], ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/PreferredMemberNodeList/3/Value, authMN=pref_MN_two, changeRule=null, cnOrc=null, cnUcsb=null, cnUnm=pref_MN_two, resulting=pref_MN_two], ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/ReplicationAllowed, authMN=true, changeRule=null, cnOrc=false, cnUcsb=true, cnUnm=true, resulting=true], ChangeRecord [id=null, pid=foo, runId=12, attribute=/RightsHolder/Value, authMN=rh_1a, changeRule=null, cnOrc=rh_1c, cnUcsb=rh_1b, cnUnm=rh_1a, resulting=rh_1c], ChangeRecord [id=null, pid=foo, runId=12, attribute=/SerialVersion, authMN=4, changeRule=null, cnOrc=5, cnUcsb=4, cnUnm=4, resulting=5]]
DEBUG[main] 2015-07-24 16:56:21,117 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: //SystemMetadata
DEBUG[main] 2015-07-24 16:56:21,123 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AccessPolicy/tidy/MaxPermissionMap/user_1
DEBUG[main] 2015-07-24 16:56:21,123 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AccessPolicy/tidy/MaxPermissionMap/user_2
DEBUG[main] 2015-07-24 16:56:21,124 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AccessPolicy/tidy/MaxPermissionMap/user_3
DEBUG[main] 2015-07-24 16:56:21,124 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Archived
DEBUG[main] 2015-07-24 16:56:21,124 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AuthoritativeMemberNode/Value
DEBUG[main] 2015-07-24 16:56:21,124 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Checksum/Algorithm
DEBUG[main] 2015-07-24 16:56:21,124 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Checksum/Value
DEBUG[main] 2015-07-24 16:56:21,125 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /DateSysMetadataModified
DEBUG[main] 2015-07-24 16:56:21,125 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /DateUploaded
DEBUG[main] 2015-07-24 16:56:21,125 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /FormatId/Value
DEBUG[main] 2015-07-24 16:56:21,125 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Identifier/Value
DEBUG[main] 2015-07-24 16:56:21,126 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ObsoletedBy
DEBUG[main] 2015-07-24 16:56:21,126 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ObsoletedBy/Value
DEBUG[main] 2015-07-24 16:56:21,126 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Obsoletes
DEBUG[main] 2015-07-24 16:56:21,126 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Obsoletes/Value
DEBUG[main] 2015-07-24 16:56:21,126 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /OriginMemberNode/Value
DEBUG[main] 2015-07-24 16:56:21,127 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicaList/tidy/FlattenedReplicas/0
DEBUG[main] 2015-07-24 16:56:21,127 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/BlockedMemberNodeList
DEBUG[main] 2015-07-24 16:56:21,127 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/BlockedMemberNodeList/0/Value
DEBUG[main] 2015-07-24 16:56:21,127 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/BlockedMemberNodeList/1/Value
DEBUG[main] 2015-07-24 16:56:21,128 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/BlockedMemberNodeList/2/Value
DEBUG[main] 2015-07-24 16:56:21,128 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/NumberReplicas
DEBUG[main] 2015-07-24 16:56:21,128 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList
DEBUG[main] 2015-07-24 16:56:21,128 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList/0/Value
DEBUG[main] 2015-07-24 16:56:21,129 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList/1/Value
DEBUG[main] 2015-07-24 16:56:21,129 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList/2/Value
DEBUG[main] 2015-07-24 16:56:21,129 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList/3/Value
DEBUG[main] 2015-07-24 16:56:21,129 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/ReplicationAllowed
DEBUG[main] 2015-07-24 16:56:21,129 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /RightsHolder/Value
DEBUG[main] 2015-07-24 16:56:21,130 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /SerialVersion
DEBUG[main] 2015-07-24 16:56:21,130 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Size
DEBUG[main] 2015-07-24 16:56:21,130 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Submitter/Value
ChangeRecord [id=null, pid=foo, runId=12, attribute=//SystemMetadata, authMN=Not Available, changeRule=null, cnOrc=Present, cnUcsb=Present, cnUnm=Present, resulting=Not Available]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/AccessPolicy/tidy/MaxPermissionMap/user_1, authMN=null, changeRule=null, cnOrc=read, cnUcsb=write, cnUnm=read, resulting=null]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/AccessPolicy/tidy/MaxPermissionMap/user_2, authMN=null, changeRule=null, cnOrc=read, cnUcsb=null, cnUnm=read, resulting=null]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/AccessPolicy/tidy/MaxPermissionMap/user_3, authMN=null, changeRule=null, cnOrc=null, cnUcsb=null, cnUnm=write, resulting=null]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/DateSysMetadataModified, authMN=null, changeRule=null, cnOrc=2006-05-04T00:00:11.000+00:00, cnUcsb=2006-05-04T00:00:13.000+00:00, cnUnm=2006-05-04T00:00:12.000+00:00, resulting=null]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ObsoletedBy/Value, authMN=null, changeRule=null, cnOrc=null, cnUcsb=AFC12352, cnUnm=AFC12352, resulting=null]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/Obsoletes/Value, authMN=null, changeRule=null, cnOrc=null, cnUcsb=AFC123, cnUnm=AFC123, resulting=null]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicaList/tidy/FlattenedReplicas/0, authMN=null, changeRule=null, cnOrc=urn:node:mn3 QUEUED 2006-05-04T18:13:51.000+00:00, cnUcsb=urn:node:mn3 COMPLETED 2006-05-04T18:13:51.000+00:00, cnUnm=urn:node:mn3 QUEUED 2006-05-04T18:13:51.000+00:00, resulting=null]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/BlockedMemberNodeList/0/Value, authMN=null, changeRule=null, cnOrc=null, cnUcsb=blocked_MN_dos, cnUnm=blocked_MN_dos, resulting=null]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/BlockedMemberNodeList/1/Value, authMN=null, changeRule=null, cnOrc=null, cnUcsb=blocked_MN_uno, cnUnm=blocked_MN_tres, resulting=null]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/BlockedMemberNodeList/2/Value, authMN=null, changeRule=null, cnOrc=null, cnUcsb=null, cnUnm=blocked_MN_uno, resulting=null]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/NumberReplicas, authMN=null, changeRule=null, cnOrc=null, cnUcsb=5, cnUnm=5, resulting=null]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/PreferredMemberNodeList/0/Value, authMN=null, changeRule=null, cnOrc=null, cnUcsb=pref_MN_four, cnUnm=pref_MN_four, resulting=null]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/PreferredMemberNodeList/1/Value, authMN=null, changeRule=null, cnOrc=null, cnUcsb=pref_MN_one, cnUnm=pref_MN_one, resulting=null]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/PreferredMemberNodeList/2/Value, authMN=null, changeRule=null, cnOrc=null, cnUcsb=pref_MN_two, cnUnm=pref_MN_three, resulting=null]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/PreferredMemberNodeList/3/Value, authMN=null, changeRule=null, cnOrc=null, cnUcsb=null, cnUnm=pref_MN_two, resulting=null]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/ReplicationPolicy/ReplicationAllowed, authMN=null, changeRule=null, cnOrc=false, cnUcsb=true, cnUnm=true, resulting=null]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/RightsHolder/Value, authMN=null, changeRule=null, cnOrc=rh_1c, cnUcsb=rh_1b, cnUnm=rh_1a, resulting=null]
ChangeRecord [id=null, pid=foo, runId=12, attribute=/SerialVersion, authMN=null, changeRule=null, cnOrc=5, cnUcsb=4, cnUnm=4, resulting=null]
DEBUG[main] 2015-07-24 16:56:21,172 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: //SystemMetadata
DEBUG[main] 2015-07-24 16:56:21,173 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AccessPolicy/tidy/MaxPermissionMap/user_1
DEBUG[main] 2015-07-24 16:56:21,173 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AccessPolicy/tidy/MaxPermissionMap/user_2
DEBUG[main] 2015-07-24 16:56:21,173 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AccessPolicy/tidy/MaxPermissionMap/user_3
DEBUG[main] 2015-07-24 16:56:21,173 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Archived
DEBUG[main] 2015-07-24 16:56:21,173 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AuthoritativeMemberNode/Value
DEBUG[main] 2015-07-24 16:56:21,173 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Checksum/Algorithm
DEBUG[main] 2015-07-24 16:56:21,174 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Checksum/Value
DEBUG[main] 2015-07-24 16:56:21,174 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /DateSysMetadataModified
DEBUG[main] 2015-07-24 16:56:21,174 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /DateUploaded
DEBUG[main] 2015-07-24 16:56:21,174 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /FormatId/Value
DEBUG[main] 2015-07-24 16:56:21,174 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Identifier/Value
DEBUG[main] 2015-07-24 16:56:21,174 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ObsoletedBy
DEBUG[main] 2015-07-24 16:56:21,175 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ObsoletedBy/Value
DEBUG[main] 2015-07-24 16:56:21,175 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Obsoletes
DEBUG[main] 2015-07-24 16:56:21,183 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Obsoletes/Value
DEBUG[main] 2015-07-24 16:56:21,183 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /OriginMemberNode/Value
DEBUG[main] 2015-07-24 16:56:21,183 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicaList/tidy/FlattenedReplicas/0
DEBUG[main] 2015-07-24 16:56:21,184 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/BlockedMemberNodeList
DEBUG[main] 2015-07-24 16:56:21,184 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/BlockedMemberNodeList/0/Value
DEBUG[main] 2015-07-24 16:56:21,184 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/BlockedMemberNodeList/1/Value
DEBUG[main] 2015-07-24 16:56:21,184 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/BlockedMemberNodeList/2/Value
DEBUG[main] 2015-07-24 16:56:21,184 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/NumberReplicas
DEBUG[main] 2015-07-24 16:56:21,184 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList
DEBUG[main] 2015-07-24 16:56:21,185 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList/0/Value
DEBUG[main] 2015-07-24 16:56:21,185 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList/1/Value
DEBUG[main] 2015-07-24 16:56:21,185 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList/2/Value
DEBUG[main] 2015-07-24 16:56:21,185 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList/3/Value
DEBUG[main] 2015-07-24 16:56:21,185 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/ReplicationAllowed
DEBUG[main] 2015-07-24 16:56:21,185 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /RightsHolder/Value
DEBUG[main] 2015-07-24 16:56:21,186 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /SerialVersion
DEBUG[main] 2015-07-24 16:56:21,186 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Size
DEBUG[main] 2015-07-24 16:56:21,186 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Submitter/Value
DEBUG[main] 2015-07-24 16:56:21,214 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: //SystemMetadata
DEBUG[main] 2015-07-24 16:56:21,215 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AccessPolicy/tidy/MaxPermissionMap/user_1
DEBUG[main] 2015-07-24 16:56:21,215 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AccessPolicy/tidy/MaxPermissionMap/user_2
DEBUG[main] 2015-07-24 16:56:21,215 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AccessPolicy/tidy/MaxPermissionMap/user_3
DEBUG[main] 2015-07-24 16:56:21,215 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Archived
DEBUG[main] 2015-07-24 16:56:21,215 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /AuthoritativeMemberNode/Value
DEBUG[main] 2015-07-24 16:56:21,216 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Checksum/Algorithm
DEBUG[main] 2015-07-24 16:56:21,216 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Checksum/Value
DEBUG[main] 2015-07-24 16:56:21,216 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /DateSysMetadataModified
DEBUG[main] 2015-07-24 16:56:21,216 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /DateUploaded
DEBUG[main] 2015-07-24 16:56:21,216 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /FormatId/Value
DEBUG[main] 2015-07-24 16:56:21,216 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Identifier/Value
DEBUG[main] 2015-07-24 16:56:21,217 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ObsoletedBy
DEBUG[main] 2015-07-24 16:56:21,217 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ObsoletedBy/Value
DEBUG[main] 2015-07-24 16:56:21,217 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Obsoletes
DEBUG[main] 2015-07-24 16:56:21,217 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Obsoletes/Value
DEBUG[main] 2015-07-24 16:56:21,217 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /OriginMemberNode/Value
DEBUG[main] 2015-07-24 16:56:21,223 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicaList/tidy/FlattenedReplicas/0
DEBUG[main] 2015-07-24 16:56:21,223 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/BlockedMemberNodeList
DEBUG[main] 2015-07-24 16:56:21,223 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/BlockedMemberNodeList/0/Value
DEBUG[main] 2015-07-24 16:56:21,224 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/NumberReplicas
DEBUG[main] 2015-07-24 16:56:21,224 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList
DEBUG[main] 2015-07-24 16:56:21,224 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList/0/Value
DEBUG[main] 2015-07-24 16:56:21,224 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList/1/Value
DEBUG[main] 2015-07-24 16:56:21,225 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList/2/Value
DEBUG[main] 2015-07-24 16:56:21,225 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/PreferredMemberNodeList/3/Value
DEBUG[main] 2015-07-24 16:56:21,225 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /ReplicationPolicy/ReplicationAllowed
DEBUG[main] 2015-07-24 16:56:21,225 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /RightsHolder/Value
DEBUG[main] 2015-07-24 16:56:21,225 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /SerialVersion
DEBUG[main] 2015-07-24 16:56:21,226 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Size
DEBUG[main] 2015-07-24 16:56:21,226 org.dataone.tidy.merge.MergeJob[254] - buildChangeReport for 'foo' check property: /Submitter/Value
Tests run: 11, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.681 sec
Running org.dataone.tidy.dao.MergeResultRepositoryTest
ERROR[main] 2015-07-24 16:56:24,609 o.h.tool.hbm2ddl.SchemaUpdate[236] - HHH000388: Unsuccessful: create index index_run on merge_result (runId)
ERROR[main] 2015-07-24 16:56:24,610 o.h.tool.hbm2ddl.SchemaUpdate[237] - Index "INDEX_RUN" already exists; SQL statement:
create index index_run on merge_result (runId) [42111-163]
page 0: MergeResult [id=1, pid=pid1, mergeDate=07/24/2015:16:56:25:447, runId=12, status=SUCCESS, authMN=null, exception='null']
page 1: MergeResult [id=2, pid=foo, mergeDate=07/24/2015:16:56:25:499, runId=12, status=SUCCESS, authMN=null, exception='null']
page 2: MergeResult [id=3, pid=bar, mergeDate=07/24/2015:16:56:25:503, runId=12, status=SUCCESS, authMN=null, exception='null']
page 3: MergeResult [id=4, pid=fu, mergeDate=07/24/2015:16:56:25:506, runId=12, status=SUCCESS, authMN=null, exception='null']
page 4: MergeResult [id=5, pid=pid2, mergeDate=07/24/2015:16:56:25:509, runId=12, status=SUCCESS, authMN=null, exception='null']
ERROR[main] 2015-07-24 16:56:25,996 o.h.tool.hbm2ddl.SchemaUpdate[236] - HHH000388: Unsuccessful: create index index_run on merge_result (runId)
ERROR[main] 2015-07-24 16:56:26,007 o.h.tool.hbm2ddl.SchemaUpdate[237] - Index "INDEX_RUN" already exists; SQL statement:
create index index_run on merge_result (runId) [42111-163]
Results found with findAll():
-------------------------------
MergeResult [id=1, pid=pid1, mergeDate=07/24/2015:16:56:25:447, runId=12, status=SUCCESS, authMN=null, exception='null']
MergeResult [id=2, pid=foo, mergeDate=07/24/2015:16:56:25:499, runId=12, status=SUCCESS, authMN=null, exception='null']
MergeResult [id=3, pid=bar, mergeDate=07/24/2015:16:56:25:503, runId=12, status=SUCCESS, authMN=null, exception='null']
MergeResult [id=4, pid=fu, mergeDate=07/24/2015:16:56:25:506, runId=12, status=SUCCESS, authMN=null, exception='null']
MergeResult [id=5, pid=pid2, mergeDate=07/24/2015:16:56:25:509, runId=12, status=SUCCESS, authMN=null, exception='null']
MergeResult [id=6, pid=pid1cn-dev-ucsb-1:RightsHolder_testGroup.14cn-dev-ucsb-1:RightsHolder_testGroup.14cn-dev-ucsb-1:RightsHolder_testGroup.14cn-dev-ucsb-1:RightsHolder_testGroup.14cn-dev-ucsb-1:Rp.14cn-dev-ucsb-1:RightsHolder_testGroup.14estGroup.14cn-dev-ucsb-1:Rp.14cn-dev-ucsb-1:RightsHolder_testGroup.14estGroup.14cn-dev-ucsb-1:Rp.14cn-dev-ucsb-1:RightsHolder_testGroup.14estGroup.14cn-dev-ucsb-1:Rp.14cn-dev-ucsb-1:RightsHolder_testGroup.14estGroup.14cn-dev-ucsb-1:Rp.14cn-dev-ucsb-1:RightsHolder_testGroup.14estGroup.14cn-dev-ucsb-1:Rp.14cn-dev-ucsb-1:RightsHolder_testGroup.14estGroup.14cn-dev-ucsb-1:Rp.14cn-dev-ucsb-1:RightsHolder_testGroup.14estGroup.14cn-dev-ucsb-1:Rp.14cn-dev-ucsb-1:RightsHolder_testGroup.14estGroup.14cn-dev-ucsb-1:Rp.14cn-dev-ucsb-1:RightsHolder_testGroup.14estGroup.14cn-dev-ucsb-1:Rp.14cn-dev-ucsb-1:RightsHolder_testGroup.14estGroup.14cn-dev-ucsb-1:Rp.14cn-dev-ucsb-1:RightsHolder_testGroup.14estGroup.14cn-dev-ucsb-1:Rp.14cn-dev-ucsb-1:RightsHolder_testGroup.14, mergeDate=07/24/2015:16:56:26:65, runId=12, status=SUCCESS, authMN=null, exception='null']
MergeResult [id=7, pid=foo, mergeDate=07/24/2015:16:56:26:69, runId=12, status=FAILURE, authMN=null, exception='null']
MergeResult [id=8, pid=bar, mergeDate=07/24/2015:16:56:26:81, runId=12, status=SUCCESS, authMN=null, exception='null']
ERROR[main] 2015-07-24 16:56:26,551 o.h.tool.hbm2ddl.SchemaUpdate[236] - HHH000388: Unsuccessful: create index index_run on merge_result (runId)
ERROR[main] 2015-07-24 16:56:26,551 o.h.tool.hbm2ddl.SchemaUpdate[237] - Index "INDEX_RUN" already exists; SQL statement:
create index index_run on merge_result (runId) [42111-163]
Tests run: 3, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 5.512 sec <<< FAILURE!
Running org.dataone.tidy.dao.SystemMetadataTidyDaoImplTest
DEBUG[main] 2015-07-24 16:56:26,824 o.d.t.dao.SystemMetadataTidyDaoImpl[186] - listIdentifiers() SQL statement: SELECT guid FROM ucsb_identifier UNION SELECT guid FROM orc_identifier UNION SELECT guid FROM unm_identifier UNION SELECT guid FROM ucsb_systemmetadata UNION SELECT guid FROM orc_systemmetadata UNION SELECT guid FROM unm_systemmetadata;
INFO [main] 2015-07-24 16:56:27,001 o.d.t.dao.SystemMetadataTidyDaoImpl[203] - ********** entering TidySysmetaDAOImpl getSysMeta ********
INFO [main] 2015-07-24 16:56:27,017 o.d.t.dao.SystemMetadataTidyDaoImpl[232] - TidySysmetaDAOImpl available sysmetas for pid: 6f632bd1cc2772bdcc43bafdbb9d8669.1.1 : 3
DEBUG[main] 2015-07-24 16:56:27,018 o.d.t.dao.SystemMetadataTidyDaoImpl[249] - urn:node:CNUNM1 = org.dataone.service.types.v1.SystemMetadata@7a0522a5
DEBUG[main] 2015-07-24 16:56:27,018 o.d.t.dao.SystemMetadataTidyDaoImpl[249] - urn:node:CNUCSB1 = org.dataone.service.types.v1.SystemMetadata@6725bd38
DEBUG[main] 2015-07-24 16:56:27,018 o.d.t.dao.SystemMetadataTidyDaoImpl[249] - urn:node:CNORC1 = org.dataone.service.types.v1.SystemMetadata@5ea9dc6f
Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.331 sec
Running org.dataone.tidy.dao.ChangeRecordRepositoryTest
ERROR[main] 2015-07-24 16:56:27,372 o.h.tool.hbm2ddl.SchemaUpdate[236] - HHH000388: Unsuccessful: create index index_run on merge_result (runId)
ERROR[main] 2015-07-24 16:56:27,373 o.h.tool.hbm2ddl.SchemaUpdate[237] - Index "INDEX_RUN" already exists; SQL statement:
create index index_run on merge_result (runId) [42111-163]
Results found with findAll():
-------------------------------
ChangeRecord [id=1, pid=pid1, runId=12, attribute=null, authMN=null, changeRule=null, cnOrc=null, cnUcsb=null, cnUnm=null, resulting=null]
ChangeRecord [id=2, pid=foo, runId=12, attribute=null, authMN=null, changeRule=null, cnOrc=null, cnUcsb=null, cnUnm=null, resulting=null]
ChangeRecord [id=3, pid=bar, runId=12, attribute=testField, authMN=urn:node:testNode, changeRule=ruleTest value, cnOrc=prevVal, cnUcsb=null, cnUnm=null, resulting=null]
Change record found with findByPid('bar'):
--------------------------------------------
ChangeRecord [id=3, pid=bar, runId=12, attribute=testField, authMN=urn:node:testNode, changeRule=ruleTest value, cnOrc=prevVal, cnUcsb=null, cnUnm=null, resulting=null]
Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.386 sec
Results :
Failed tests: testSimpleCreateReadTest(org.dataone.tidy.dao.MergeResultRepositoryTest): Total records found did not match expected. expected:<3> but was:<8>
Tests run: 54, Failures: 1, Errors: 0, Skipped: 0
[ERROR] There are test failures.
Please refer to /var/lib/jenkins/jobs/d1_tidy_sysmeta/workspace/d1_tidy_sysmeta/target/surefire-reports for the individual test results.
[JENKINS] Recording test results
[INFO]
[INFO] --- maven-resources-plugin:2.4.3:copy-resources (include-src-resources-afterTests) @ d1-tidy-sysmeta ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] Copying 5 resources
[INFO]
[INFO] --- maven-jar-plugin:2.2:jar (default-jar) @ d1-tidy-sysmeta ---
[INFO] Building jar: /var/lib/jenkins/jobs/d1_tidy_sysmeta/workspace/d1_tidy_sysmeta/target/d1-tidy-sysmeta-1.0.0-SNAPSHOT.jar
[INFO]
[INFO] --- maven-shade-plugin:2.2:shade (default) @ d1-tidy-sysmeta ---
[INFO] Including org.slf4j:slf4j-api:jar:1.7.5 in the shaded jar.
[INFO] Including org.slf4j:jcl-over-slf4j:jar:1.7.5 in the shaded jar.
[INFO] Including org.slf4j:log4j-over-slf4j:jar:1.7.5 in the shaded jar.
[INFO] Including ch.qos.logback:logback-classic:jar:1.0.13 in the shaded jar.
[INFO] Including ch.qos.logback:logback-core:jar:1.0.13 in the shaded jar.
[INFO] Including org.dataone:d1_libclient_java:jar:1.3.0-SNAPSHOT in the shaded jar.
[INFO] Including net.sf.jsignature.io-tools:easystream:jar:1.2.12 in the shaded jar.
[INFO] Including commons-collections:commons-collections:jar:3.2.1 in the shaded jar.
[INFO] Including javax.mail:mail:jar:1.4.1 in the shaded jar.
[INFO] Including javax.activation:activation:jar:1.1 in the shaded jar.
[INFO] Including org.jibx:jibx-run:jar:1.2.4.5 in the shaded jar.
[INFO] Including xpp3:xpp3:jar:1.1.3.4.O in the shaded jar.
[INFO] Including org.bouncycastle:bcprov-jdk16:jar:1.46 in the shaded jar.
[INFO] Including commons-lang:commons-lang:jar:2.6 in the shaded jar.
[INFO] Including org.apache.httpcomponents:httpclient:jar:4.1.3 in the shaded jar.
[INFO] Including org.apache.httpcomponents:httpcore:jar:4.1.4 in the shaded jar.
[INFO] Including commons-codec:commons-codec:jar:1.4 in the shaded jar.
[INFO] Including com.googlecode.foresite-toolkit:foresite:jar:1.0-SNAPSHOT in the shaded jar.
[INFO] Including com.hp.hpl.jena:jena:jar:2.5.5 in the shaded jar.
[INFO] Including com.hp.hpl.jena:arq:jar:2.2 in the shaded jar.
[INFO] Including com.hp.hpl.jena:arq-extra:jar:2.2 in the shaded jar.
[INFO] Including com.hp.hpl.jena:jenatest:jar:2.5.5 in the shaded jar.
[INFO] Including com.hp.hpl.jena:iri:jar:0.5 in the shaded jar.
[INFO] Including com.hp.hpl.jena:concurrent-jena:jar:1.3.2 in the shaded jar.
[INFO] Including com.ibm.icu:icu4j:jar:3.4.4 in the shaded jar.
[INFO] Including com.hp.hpl.jena:json-jena:jar:1.0 in the shaded jar.
[INFO] Including stax:stax-api:jar:1.0 in the shaded jar.
[INFO] Including xerces:xmlParserAPIs:jar:2.0.2 in the shaded jar.
[INFO] Including rome:rome:jar:0.9 in the shaded jar.
[INFO] Including jdom:jdom:jar:1.0 in the shaded jar.
[INFO] Including xalan:xalan:jar:2.7.0 in the shaded jar.
[INFO] Including commons-cli:commons-cli:jar:1.0 in the shaded jar.
[INFO] Including jcs:jcs:jar:1.3 in the shaded jar.
[INFO] Including concurrent:concurrent:jar:1.0 in the shaded jar.
[INFO] Including mysql:mysql-connector-java:jar:3.0.10 in the shaded jar.
[INFO] Including javax.sql:jdbc-stdext:jar:2.0 in the shaded jar.
[INFO] Including javax.transaction:jta:jar:1.0.1B in the shaded jar.
[INFO] Including hsqldb:hsqldb:jar:1.7.3.3 in the shaded jar.
[INFO] Including javax.servlet:servlet-api:jar:2.3 in the shaded jar.
[INFO] Including tomcat:tomcat-util:jar:3.2.1 in the shaded jar.
[INFO] Including velocity:velocity:jar:1.5 in the shaded jar.
[INFO] Including oro:oro:jar:2.0.8 in the shaded jar.
[INFO] Including xmlrpc:xmlrpc:jar:2.0 in the shaded jar.
[INFO] Including xerces:xercesImpl:jar:2.6.2 in the shaded jar.
[INFO] Including xml-apis:xml-apis:jar:1.0.b2 in the shaded jar.
[INFO] Including berkeleydb:berkeleydb:jar:1.5.1 in the shaded jar.
[INFO] Including org.dataone:d1_common_java:jar:1.3.0-SNAPSHOT in the shaded jar.
[INFO] Including org.jibx:maven-jibx-plugin:jar:1.2.4.5 in the shaded jar.
[INFO] Including org.apache.maven:maven-plugin-api:jar:2.2.1 in the shaded jar.
[INFO] Including org.apache.maven:maven-project:jar:2.2.1 in the shaded jar.
[INFO] Including org.apache.maven:maven-settings:jar:2.2.1 in the shaded jar.
[INFO] Including org.apache.maven:maven-profile:jar:2.2.1 in the shaded jar.
[INFO] Including org.apache.maven:maven-artifact-manager:jar:2.2.1 in the shaded jar.
[INFO] Including backport-util-concurrent:backport-util-concurrent:jar:3.1 in the shaded jar.
[INFO] Including org.apache.maven:maven-plugin-registry:jar:2.2.1 in the shaded jar.
[INFO] Including org.codehaus.plexus:plexus-interpolation:jar:1.11 in the shaded jar.
[INFO] Including org.jibx:jibx-tools:jar:1.2.4.5 in the shaded jar.
[INFO] Including org.jibx:jibx-schema:jar:1.2.4.5 in the shaded jar.
[INFO] Including org.jibx.config.3rdparty.org.eclipse:org.eclipse.core.contenttype:jar:3.4.100.v20110423-0524 in the shaded jar.
[INFO] Including org.jibx.config.3rdparty.org.eclipse:org.eclipse.core.jobs:jar:3.5.100.v20110404 in the shaded jar.
[INFO] Including org.jibx.config.3rdparty.org.eclipse:org.eclipse.core.resources:jar:3.7.100.v20110510-0712 in the shaded jar.
[INFO] Including org.jibx.config.3rdparty.org.eclipse:org.eclipse.core.runtime:jar:3.7.0.v20110110 in the shaded jar.
[INFO] Including org.jibx.config.3rdparty.org.eclipse:org.eclipse.equinox.common:jar:3.6.0.v20110523 in the shaded jar.
[INFO] Including org.jibx.config.3rdparty.org.eclipse:org.eclipse.equinox.preferences:jar:3.4.0.v20110502 in the shaded jar.
[INFO] Including org.jibx.config.3rdparty.org.eclipse:org.eclipse.jdt.core:jar:3.7.0.v_B61 in the shaded jar.
[INFO] Including org.jibx.config.3rdparty.org.eclipse:org.eclipse.osgi:jar:3.7.0.v20110613 in the shaded jar.
[INFO] Including org.jibx.config.3rdparty.org.eclipse:org.eclipse.text:jar:3.5.100.v20110505-0800 in the shaded jar.
[INFO] Including org.jibx:jibx-bind:jar:1.2.4.5 in the shaded jar.
[INFO] Including bcel:bcel:jar:5.1 in the shaded jar.
[INFO] Including regexp:regexp:jar:1.2 in the shaded jar.
[INFO] Including org.jibx:jibx-extras:jar:1.2.4.5 in the shaded jar.
[INFO] Including org.jdom:jdom:jar:1.1.3 in the shaded jar.
[INFO] Including org.codehaus.plexus:plexus-utils:jar:2.0.5 in the shaded jar.
[INFO] Including com.thoughtworks.qdox:qdox:jar:1.12 in the shaded jar.
[INFO] Including joda-time:joda-time:jar:2.1 in the shaded jar.
[INFO] Including org.apache.maven.plugins:maven-compiler-plugin:maven-plugin:2.3.1 in the shaded jar.
[INFO] Including org.codehaus.plexus:plexus-container-default:jar:1.0-alpha-9-stable-1 in the shaded jar.
[INFO] Including classworlds:classworlds:jar:1.1-alpha-2 in the shaded jar.
[INFO] Including org.apache.maven:maven-artifact:jar:2.0.6 in the shaded jar.
[INFO] Including org.apache.maven:maven-core:jar:2.0.6 in the shaded jar.
[INFO] Including org.apache.maven.wagon:wagon-file:jar:1.0-beta-2 in the shaded jar.
[INFO] Including org.apache.maven:maven-plugin-parameter-documenter:jar:2.0.6 in the shaded jar.
[INFO] Including org.apache.maven.wagon:wagon-http-lightweight:jar:1.0-beta-2 in the shaded jar.
[INFO] Including org.apache.maven.wagon:wagon-http-shared:jar:1.0-beta-2 in the shaded jar.
[INFO] Including jtidy:jtidy:jar:4aug2000r7-dev in the shaded jar.
[INFO] Including org.apache.maven.reporting:maven-reporting-api:jar:2.0.6 in the shaded jar.
[INFO] Including org.apache.maven.doxia:doxia-sink-api:jar:1.0-alpha-7 in the shaded jar.
[INFO] Including org.apache.maven.wagon:wagon-provider-api:jar:1.0-beta-2 in the shaded jar.
[INFO] Including org.apache.maven:maven-repository-metadata:jar:2.0.6 in the shaded jar.
[INFO] Including org.apache.maven:maven-error-diagnostics:jar:2.0.6 in the shaded jar.
[INFO] Including org.apache.maven.wagon:wagon-ssh-external:jar:1.0-beta-2 in the shaded jar.
[INFO] Including org.apache.maven.wagon:wagon-ssh-common:jar:1.0-beta-2 in the shaded jar.
[INFO] Including org.apache.maven:maven-plugin-descriptor:jar:2.0.6 in the shaded jar.
[INFO] Including org.codehaus.plexus:plexus-interactivity-api:jar:1.0-alpha-4 in the shaded jar.
[INFO] Including org.apache.maven:maven-monitor:jar:2.0.6 in the shaded jar.
[INFO] Including org.apache.maven.wagon:wagon-ssh:jar:1.0-beta-2 in the shaded jar.
[INFO] Including com.jcraft:jsch:jar:0.1.27 in the shaded jar.
[INFO] Including org.codehaus.plexus:plexus-compiler-api:jar:1.8 in the shaded jar.
[INFO] Including org.apache.maven:maven-toolchain:jar:1.0 in the shaded jar.
[INFO] Including org.codehaus.plexus:plexus-compiler-manager:jar:1.8 in the shaded jar.
[INFO] Including org.codehaus.plexus:plexus-compiler-javac:jar:1.8 in the shaded jar.
[INFO] Including org.apache.maven.plugins:maven-jar-plugin:maven-plugin:2.3.1 in the shaded jar.
[INFO] Including org.apache.maven:maven-model:jar:2.0.6 in the shaded jar.
[INFO] Including org.apache.maven:maven-archiver:jar:2.4.1 in the shaded jar.
[INFO] Including org.codehaus.plexus:plexus-archiver:jar:1.0 in the shaded jar.
[INFO] Including org.codehaus.plexus:plexus-io:jar:1.0 in the shaded jar.
[INFO] Including org.apache.maven.plugins:maven-clean-plugin:maven-plugin:2.4.1 in the shaded jar.
[INFO] Including commons-fileupload:commons-fileupload:jar:1.2.2 in the shaded jar.
[INFO] Including org.apache.httpcomponents:httpmime:jar:4.2.3 in the shaded jar.
[INFO] Including commons-configuration:commons-configuration:jar:1.7 in the shaded jar.
[INFO] Including commons-digester:commons-digester:jar:1.8.1 in the shaded jar.
[INFO] Including commons-beanutils:commons-beanutils:jar:1.8.3 in the shaded jar.
[INFO] Including commons-io:commons-io:jar:2.0.1 in the shaded jar.
[INFO] Including org.dataone:d1_jibx_extensions:jar:1.2.0-SNAPSHOT in the shaded jar.
[INFO] Including org.dataone:d1_cn_common:jar:1.2.0-SNAPSHOT in the shaded jar.
[INFO] Including com.hazelcast:hazelcast:jar:2.4.1 in the shaded jar.
[INFO] Including com.hazelcast:hazelcast-client:jar:2.4.1 in the shaded jar.
[INFO] Including org.apache.solr:solr-solrj:jar:3.4.0 in the shaded jar.
[INFO] Including org.apache.lucene:lucene-core:jar:3.4.0 in the shaded jar.
[INFO] Including commons-httpclient:commons-httpclient:jar:3.1 in the shaded jar.
[INFO] Including org.apache.geronimo.specs:geronimo-stax-api_1.0_spec:jar:1.0.1 in the shaded jar.
[INFO] Including org.apache.zookeeper:zookeeper:jar:3.3.1 in the shaded jar.
[INFO] Including jline:jline:jar:0.9.94 in the shaded jar.
[INFO] Including org.codehaus.woodstox:wstx-asl:jar:3.2.7 in the shaded jar.
[INFO] Including org.springframework:spring-core:jar:3.1.1.RELEASE in the shaded jar.
[INFO] Including org.springframework:spring-asm:jar:3.1.1.RELEASE in the shaded jar.
[INFO] Including org.springframework:spring-jdbc:jar:3.1.1.RELEASE in the shaded jar.
[INFO] Including org.springframework:spring-tx:jar:3.1.1.RELEASE in the shaded jar.
[INFO] Including aopalliance:aopalliance:jar:1.0 in the shaded jar.
[INFO] Including org.dataone:d1_cn_noderegistry:jar:1.3.0-SNAPSHOT in the shaded jar.
[INFO] Including org.springframework.data:spring-data-jpa:jar:1.4.3.RELEASE in the shaded jar.
[INFO] Including org.springframework.data:spring-data-commons:jar:1.6.3.RELEASE in the shaded jar.
[INFO] Including org.springframework:spring-orm:jar:3.1.4.RELEASE in the shaded jar.
[INFO] Including org.springframework:spring-context:jar:3.1.4.RELEASE in the shaded jar.
[INFO] Including org.springframework:spring-expression:jar:3.1.4.RELEASE in the shaded jar.
[INFO] Including org.springframework:spring-aop:jar:3.1.4.RELEASE in the shaded jar.
[INFO] Including org.springframework:spring-beans:jar:3.1.4.RELEASE in the shaded jar.
[INFO] Including org.aspectj:aspectjrt:jar:1.7.2 in the shaded jar.
[INFO] Including org.hibernate:hibernate-entitymanager:jar:4.2.1.Final in the shaded jar.
[INFO] Including org.jboss.logging:jboss-logging:jar:3.1.0.GA in the shaded jar.
[INFO] Including org.hibernate:hibernate-core:jar:4.2.1.Final in the shaded jar.
[INFO] Including antlr:antlr:jar:2.7.7 in the shaded jar.
[INFO] Including dom4j:dom4j:jar:1.6.1 in the shaded jar.
[INFO] Including org.jboss.spec.javax.transaction:jboss-transaction-api_1.1_spec:jar:1.0.1.Final in the shaded jar.
[INFO] Including org.hibernate.javax.persistence:hibernate-jpa-2.0-api:jar:1.0.1.Final in the shaded jar.
[INFO] Including org.javassist:javassist:jar:3.15.0-GA in the shaded jar.
[INFO] Including org.hibernate.common:hibernate-commons-annotations:jar:4.0.1.Final in the shaded jar.
[INFO] Including cglib:cglib:jar:3.1 in the shaded jar.
[INFO] Including org.ow2.asm:asm:jar:4.2 in the shaded jar.
[INFO] Including commons-dbcp:commons-dbcp:jar:1.2.2 in the shaded jar.
[INFO] Including commons-pool:commons-pool:jar:1.3 in the shaded jar.
[INFO] Including postgresql:postgresql:jar:8.4-702.jdbc4 in the shaded jar.
[INFO] Including commons-logging:commons-logging:jar:1.1.1 in the shaded jar.
[WARNING] jta-1.0.1B.jar, jboss-transaction-api_1.1_spec-1.0.1.Final.jar define 17 overlappping classes:
[WARNING] - javax.transaction.RollbackException
[WARNING] - javax.transaction.HeuristicMixedException
[WARNING] - javax.transaction.InvalidTransactionException
[WARNING] - javax.transaction.xa.XAException
[WARNING] - javax.transaction.Synchronization
[WARNING] - javax.transaction.HeuristicRollbackException
[WARNING] - javax.transaction.HeuristicCommitException
[WARNING] - javax.transaction.xa.XAResource
[WARNING] - javax.transaction.TransactionRolledbackException
[WARNING] - javax.transaction.NotSupportedException
[WARNING] - 7 more...
[WARNING] xml-apis-1.0.b2.jar, jtidy-4aug2000r7-dev.jar, xmlrpc-2.0.jar, xmlParserAPIs-2.0.2.jar define 11 overlappping classes:
[WARNING] - org.xml.sax.SAXException
[WARNING] - org.xml.sax.HandlerBase
[WARNING] - org.xml.sax.DTDHandler
[WARNING] - org.xml.sax.SAXParseException
[WARNING] - org.xml.sax.ErrorHandler
[WARNING] - org.xml.sax.AttributeList
[WARNING] - org.xml.sax.InputSource
[WARNING] - org.xml.sax.DocumentHandler
[WARNING] - org.xml.sax.EntityResolver
[WARNING] - org.xml.sax.Locator
[WARNING] - 1 more...
[WARNING] xml-apis-1.0.b2.jar, xmlParserAPIs-2.0.2.jar define 92 overlappping classes:
[WARNING] - javax.xml.parsers.SAXParser
[WARNING] - javax.xml.parsers.SAXParserFactory
[WARNING] - org.w3c.dom.html.HTMLTextAreaElement
[WARNING] - javax.xml.parsers.FactoryConfigurationError
[WARNING] - org.w3c.dom.html.HTMLQuoteElement
[WARNING] - org.w3c.dom.html.HTMLBaseFontElement
[WARNING] - org.w3c.dom.traversal.DocumentTraversal
[WARNING] - org.w3c.dom.html.HTMLLabelElement
[WARNING] - org.xml.sax.helpers.AttributesImpl
[WARNING] - org.w3c.dom.ranges.Range
[WARNING] - 82 more...
[WARNING] jcl-over-slf4j-1.7.5.jar, commons-logging-1.1.1.jar define 6 overlappping classes:
[WARNING] - org.apache.commons.logging.impl.NoOpLog
[WARNING] - org.apache.commons.logging.impl.SimpleLog
[WARNING] - org.apache.commons.logging.LogFactory
[WARNING] - org.apache.commons.logging.LogConfigurationException
[WARNING] - org.apache.commons.logging.impl.SimpleLog$1
[WARNING] - org.apache.commons.logging.Log
[WARNING] xercesImpl-2.6.2.jar, xmlParserAPIs-2.0.2.jar define 1 overlappping classes:
[WARNING] - org.w3c.dom.html.HTMLDOMImplementation
[WARNING] xpp3-1.1.3.4.O.jar, stax-api-1.0.jar define 1 overlappping classes:
[WARNING] - javax.xml.namespace.QName
[WARNING] commons-beanutils-1.8.3.jar, commons-collections-3.2.1.jar define 10 overlappping classes:
[WARNING] - org.apache.commons.collections.FastHashMap$EntrySet
[WARNING] - org.apache.commons.collections.ArrayStack
[WARNING] - org.apache.commons.collections.FastHashMap$1
[WARNING] - org.apache.commons.collections.FastHashMap$KeySet
[WARNING] - org.apache.commons.collections.FastHashMap$CollectionView
[WARNING] - org.apache.commons.collections.BufferUnderflowException
[WARNING] - org.apache.commons.collections.Buffer
[WARNING] - org.apache.commons.collections.FastHashMap$CollectionView$CollectionViewIterator
[WARNING] - org.apache.commons.collections.FastHashMap$Values
[WARNING] - org.apache.commons.collections.FastHashMap
[WARNING] jdom-1.1.3.jar, jdom-1.0.jar define 72 overlappping classes:
[WARNING] - org.jdom.filter.ElementFilter
[WARNING] - org.jdom.transform.JDOMSource$JDOMInputSource
[WARNING] - org.jdom.adapters.OracleV2DOMAdapter
[WARNING] - org.jdom.Content
[WARNING] - org.jdom.JDOMException
[WARNING] - org.jdom.filter.ContentFilter
[WARNING] - org.jdom.transform.XSLTransformer
[WARNING] - org.jdom.IllegalDataException
[WARNING] - org.jdom.adapters.OracleV1DOMAdapter
[WARNING] - org.jdom.CDATA
[WARNING] - 62 more...
[WARNING] stax-api-1.0.jar, geronimo-stax-api_1.0_spec-1.0.1.jar define 33 overlappping classes:
[WARNING] - javax.xml.stream.XMLOutputFactory
[WARNING] - javax.xml.stream.events.StartElement
[WARNING] - javax.xml.stream.events.Namespace
[WARNING] - javax.xml.stream.util.EventReaderDelegate
[WARNING] - javax.xml.stream.XMLInputFactory
[WARNING] - javax.xml.stream.events.Characters
[WARNING] - javax.xml.stream.XMLStreamReader
[WARNING] - javax.xml.stream.events.EntityReference
[WARNING] - javax.xml.stream.StreamFilter
[WARNING] - javax.xml.stream.events.NotationDeclaration
[WARNING] - 23 more...
[WARNING] xml-apis-1.0.b2.jar, jtidy-4aug2000r7-dev.jar, xmlParserAPIs-2.0.2.jar define 24 overlappping classes:
[WARNING] - org.w3c.dom.Document
[WARNING] - org.w3c.dom.Attr
[WARNING] - org.w3c.dom.Node
[WARNING] - org.w3c.dom.EntityReference
[WARNING] - org.xml.sax.XMLReader
[WARNING] - org.w3c.dom.Notation
[WARNING] - org.w3c.dom.ProcessingInstruction
[WARNING] - org.w3c.dom.Entity
[WARNING] - org.w3c.dom.DOMImplementation
[WARNING] - org.w3c.dom.Element
[WARNING] - 14 more...
[WARNING] concurrent-jena-1.3.2.jar, concurrent-1.0.jar define 140 overlappping classes:
[WARNING] - EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop
[WARNING] - EDU.oswego.cs.dl.util.concurrent.ClockDaemon$TaskNode
[WARNING] - EDU.oswego.cs.dl.util.concurrent.LinkedQueue
[WARNING] - EDU.oswego.cs.dl.util.concurrent.WaitableLong
[WARNING] - EDU.oswego.cs.dl.util.concurrent.BoundedLinkedQueue
[WARNING] - EDU.oswego.cs.dl.util.concurrent.PooledExecutor$DiscardOldestWhenBlocked
[WARNING] - EDU.oswego.cs.dl.util.concurrent.SynchronizedFloat
[WARNING] - EDU.oswego.cs.dl.util.concurrent.ReaderPreferenceReadWriteLock
[WARNING] - EDU.oswego.cs.dl.util.concurrent.PooledExecutor$AbortWhenBlocked
[WARNING] - EDU.oswego.cs.dl.util.concurrent.ConcurrentHashMap$KeySet
[WARNING] - 130 more...
[WARNING] maven-shade-plugin has detected that some .class files
[WARNING] are present in two or more JARs. When this happens, only
[WARNING] one single version of the class is copied in the uberjar.
[WARNING] Usually this is not harmful and you can skeep these
[WARNING] warnings, otherwise try to manually exclude artifacts
[WARNING] based on mvn dependency:tree -Ddetail=true and the above
[WARNING] output
[WARNING] See http://docs.codehaus.org/display/MAVENUSER/Shade+Plugin
[INFO]
[INFO] --- maven-install-plugin:2.3:install (default-install) @ d1-tidy-sysmeta ---
[INFO] Installing /var/lib/jenkins/jobs/d1_tidy_sysmeta/workspace/d1_tidy_sysmeta/target/d1-tidy-sysmeta-1.0.0-SNAPSHOT.jar to /var/lib/jenkins/.m2/repository/org/dataone/d1-tidy-sysmeta/1.0.0-SNAPSHOT/d1-tidy-sysmeta-1.0.0-SNAPSHOT.jar
[INFO] Installing /var/lib/jenkins/jobs/d1_tidy_sysmeta/workspace/d1_tidy_sysmeta/pom.xml to /var/lib/jenkins/.m2/repository/org/dataone/d1-tidy-sysmeta/1.0.0-SNAPSHOT/d1-tidy-sysmeta-1.0.0-SNAPSHOT.pom
Notifying upstream projects of job completion
Join notifier requires a CauseAction
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 57.450s
[INFO] Finished at: Fri Jul 24 16:56:44 UTC 2015
[INFO] Final Memory: 51M/427M
[INFO] ------------------------------------------------------------------------
Waiting for Jenkins to finish collecting data
![[Jenkins]](/jenkins/static/b611b658/images/jenkins-header-logo-v2.svg){kind=logo}
