Troubleshoot DrawActionTest.testTicket12011

[Don-vip]

For quite some time we have an unstable test:

org.openstreetmap.josm.actions.mapmode.DrawActionTest.testTicket12011

It fails quite often, more often when the server is stressed. The fact that the error is a timeout makes me think we have a race condition leading to a deadlock.

Any help welcome to diagnose the error as I can't find enough time to do it.

[wiktorn]

I took a look at it. Relevant thread dump:

"AWT-EventQueue-0" #147 prio=6 os_prio=0 tid=0x00007fe56c073800 nid=0xc5a waiting on condition [0x00007fe576fc0000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000ec253bd8> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
        at java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:943)
        at org.openstreetmap.josm.data.osm.DataSet.beginUpdate(DataSet.java:928)
        at org.openstreetmap.josm.data.osm.OsmPrimitive.writeLock(OsmPrimitive.java:260)
        at org.openstreetmap.josm.data.osm.OsmPrimitive.updateFlags(OsmPrimitive.java:373)
        at org.openstreetmap.josm.data.osm.OsmPrimitive.setHighlighted(OsmPrimitive.java:596)
        at org.openstreetmap.josm.actions.mapmode.DrawAction.redrawIfRequired(DrawAction.java:214)
        at org.openstreetmap.josm.actions.mapmode.DrawAction.addHighlighting(DrawAction.java:1192)
        at org.openstreetmap.josm.actions.mapmode.DrawAction.lambda$selectionChanged$4(DrawAction.java:398)
        at org.openstreetmap.josm.actions.mapmode.DrawAction$$Lambda$436/916951528.run(Unknown Source)
        at java.awt.event.InvocationEvent.dispatch(InvocationEvent.java:311)
        at java.awt.EventQueue.dispatchEventImpl(EventQueue.java:758)
        at java.awt.EventQueue.access$500(EventQueue.java:97)
        at java.awt.EventQueue$3.run(EventQueue.java:709)
        at java.awt.EventQueue$3.run(EventQueue.java:703)
        at java.security.AccessController.doPrivileged(Native Method)
        at java.security.ProtectionDomain$JavaSecurityAccessImpl.doIntersectionPrivilege(ProtectionDomain.java:74)
        at java.awt.EventQueue.dispatchEvent(EventQueue.java:728)
        at java.awt.EventDispatchThread.pumpOneEventForFilters(EventDispatchThread.java:205)
        at java.awt.EventDispatchThread.pumpEventsForFilter(EventDispatchThread.java:116)
        at java.awt.EventDispatchThread.pumpEventsForHierarchy(EventDispatchThread.java:105)
        at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:101)
        at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:93)
        at java.awt.EventDispatchThread.run(EventDispatchThread.java:82)

"main" #1 prio=5 os_prio=0 tid=0x00007fe60400e800 nid=0xbc4 in Object.wait() [0x00007fe60b152000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at java.lang.Object.wait(Object.java:502)
        at java.awt.EventQueue.invokeAndWait(EventQueue.java:1343)
        - locked <0x00000000ec311f48> (a java.awt.EventQueue$1AWTInvocationLock)
        at java.awt.EventQueue.invokeAndWait(EventQueue.java:1324)
        at javax.swing.SwingUtilities.invokeAndWait(SwingUtilities.java:1353)
        at org.openstreetmap.josm.gui.util.GuiHelper.runInEDTAndWaitWithException(GuiHelper.java:240)
        at org.openstreetmap.josm.data.osm.event.SelectionEventManager.selectionChanged(SelectionEventManager.java:217)
        at org.openstreetmap.josm.data.osm.DataSet.lambda$doSelectionChange$6(DataSet.java:733)
        at org.openstreetmap.josm.data.osm.DataSet$$Lambda$137/2063174772.fire(Unknown Source)
        at org.openstreetmap.josm.tools.ListenerList.fireEvent(ListenerList.java:150)
        at org.openstreetmap.josm.data.osm.DataSet.doSelectionChange(DataSet.java:733)
        - locked <0x00000000ec253c38> (a java.lang.Object)
        at org.openstreetmap.josm.data.osm.DataSet.clearSelection(DataSet.java:699)
        at org.openstreetmap.josm.data.osm.DataSet.clearSelection(DataSet.java:685)
        at org.openstreetmap.josm.data.osm.DataSet.removePrimitiveImpl(DataSet.java:509)
        at org.openstreetmap.josm.data.osm.DataSet.removePrimitive(DataSet.java:501)
        at org.openstreetmap.josm.command.AddCommand.undoCommand(AddCommand.java:62)
        at org.openstreetmap.josm.command.SequenceCommand.undoCommands(SequenceCommand.java:101)
        at org.openstreetmap.josm.command.SequenceCommand.undoCommand(SequenceCommand.java:111)
        at org.openstreetmap.josm.data.UndoRedoHandler.undo(UndoRedoHandler.java:300)
        - locked <0x00000000c25191d8> (a org.openstreetmap.josm.data.UndoRedoHandler)
        at org.openstreetmap.josm.data.UndoRedoHandler.undo(UndoRedoHandler.java:283)
        at org.openstreetmap.josm.actions.mapmode.DrawActionTest.testTicket12011(DrawActionTest.java:94)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
        at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
        at mockit.integration.junit4.internal.JUnit4TestRunnerDecorator.executeTestMethod(JUnit4TestRunnerDecorator.java:154)
        at mockit.integration.junit4.internal.JUnit4TestRunnerDecorator.invokeExplosively(JUnit4TestRunnerDecorator.java:70)
        at mockit.integration.junit4.internal.FakeFrameworkMethod.invokeExplosively(FakeFrameworkMethod.java:33)
        at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java)
        at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
        at org.openstreetmap.josm.testutils.JOSMTestRules$CreateJosmEnvironment.evaluate(JOSMTestRules.java:623)
        at org.junit.rules.RunRules.evaluate(RunRules.java:20)
        at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
        at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
        at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
        at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
        at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
        at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:38)
        at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:536)
        at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:1205)

Monitor addresses doesn't match, but looking at the code, it looks like we have following code in UndoRedoHandler:

    public synchronized void undo(int num) {
       [...]
            ds.beginUpdate();

We acquire DataSet write lock in UndoRedoHandler in main thread and runInEDTAndWaits to process selectionChangedEvents. And in DrawAction.selectionChanged we try to require lock on DataSet because we change highligted element.

First solution that comes to my mind is to move whole UndoRedoHandler.undo to EDT thread so the locking will occur within the same thread and problem will not occur.

I'm not sure what kind of race we have here, that the code takes different path. I guess that it might be connected with which primitve gets highlighted or something.

[Don-vip]

Replying to wiktorn:

I took a look at it.

Thanks!

First solution that comes to my mind is to move whole UndoRedoHandler.undo to EDT thread so the locking will occur within the same thread and problem will not occur.

No better idea, I think we can give it a try.

[wiktorn]

In 14204/josm:

Move undo handler to EDT

To prevent live-locks when undo is called outside EDT and locks DataSet, and
DrawAction.selectionChanged tries to reaquire this lock in EDT thread.

Also - add synchronized keyword to redo and clean, to be symetrical with undo.

Closes: #16679