Issue2536

classification
Title: test_logging deadlocks during regrtest
Type: Severity: normal
Components: Core Versions:
Milestone:
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: stefan.richthofer, zyasoft
Priority: Keywords:

Created on 2016-12-01.14:43:27 by stefan.richthofer, last changed 2016-12-01.14:43:27 by stefan.richthofer.

Files
File name Uploaded Description Edit Remove
test_logging_hangs.txt stefan.richthofer, 2016-12-01.14:43:25 full jstack-output while test_logging deadlocks.
Messages
msg10996 (view) Author: Stefan Richthofer (stefan.richthofer) Date: 2016-12-01.14:43:25
Running on Linux Mint 18, 64 Bit with Java 8 I observe a deadlock in test_logging.py from time to time. It only occurs when running with 'ant regrtest' and the test itself does not give output or error, regrtest just hangs indefinitely.

jstack reports a deadlock (full output attached):


Found one Java-level deadlock:
=============================
"Thread-262":
  waiting for ownable synchronizer 0x00000000e06df030, (a java.util.concurrent.locks.ReentrantLock$NonfairSync),
  which is held by "MainThread"
"MainThread":
  waiting for ownable synchronizer 0x00000000e0787518, (a java.util.concurrent.locks.ReentrantLock$NonfairSync),
  which is held by "Thread-262"

Java stack information for the threads listed above:
===================================================
"Thread-262":
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000000e06df030> (a java.util.concurrent.locks.ReentrantLock$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.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
	at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
	at com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2228)
	at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2208)
	at com.google.common.cache.LocalCache.get(LocalCache.java:4053)
	at com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:4057)
	at com.google.common.cache.LocalCache$LocalLoadingCache.get(LocalCache.java:4986)
	at com.google.common.cache.LocalCache$LocalLoadingCache.getUnchecked(LocalCache.java:4992)
	at org.python.modules.sre.SRE_STATE$CACHE.get(SRE_STATE.java:1290)
	at org.python.modules.sre.SRE_STATE$CACHE.access$000(SRE_STATE.java:1253)
	at org.python.modules.sre.SRE_STATE.<init>(SRE_STATE.java:1295)
	at org.python.modules.sre.PatternObject.match(PatternObject.java:80)
	at org.python.modules.sre.PatternObject$match_exposer.__call__(Unknown Source)
	at org.python.core.PyObject.__call__(PyObject.java:480)
	at org.python.core.PyObject.__call__(PyObject.java:484)
	at logging.config$py.valid_ident$10(logging/config.py:275)
	at logging.config$py.call_function(logging/config.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:139)
	at org.python.core.PyFunction.__call__(PyFunction.java:413)
	at logging.config$py.configure_handler$33(logging/config.py:732)
	at logging.config$py.call_function(logging/config.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:154)
	at org.python.core.PyFunction.__call__(PyFunction.java:423)
	at org.python.core.PyMethod.__call__(PyMethod.java:141)
	at logging.config$py.configure$29(logging/config.py:640)
	at logging.config$py.call_function(logging/config.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:139)
	at org.python.core.PyFunction.__call__(PyFunction.java:413)
	at org.python.core.PyMethod.__call__(PyMethod.java:126)
	at logging.config$py.dictConfig$38(logging/config.py:777)
	at logging.config$py.call_function(logging/config.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:139)
	at org.python.core.PyFunction.__call__(PyFunction.java:413)
	at logging.config$py.handle$41(logging/config.py:840)
	at logging.config$py.call_function(logging/config.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:139)
	at org.python.core.PyFunction.__call__(PyFunction.java:413)
	at org.python.core.PyMethod.__call__(PyMethod.java:126)
	at SocketServer$py.__init__$47(SocketServer.py:659)
	at SocketServer$py.call_function(SocketServer.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:308)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:199)
	at org.python.core.PyFunction.__call__(PyFunction.java:482)
	at org.python.core.PyFunction.__call__(PyFunction.java:476)
	at org.python.core.PyInstance.__init__(PyInstance.java:124)
	at org.python.core.PyClass.__call__(PyClass.java:193)
	at org.python.core.PyObject.__call__(PyObject.java:515)
	at org.python.core.PyObject.__call__(PyObject.java:519)
	at SocketServer$py.finish_request$13(SocketServer.py:334)
	at SocketServer$py.call_function(SocketServer.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:171)
	at org.python.core.PyFunction.__call__(PyFunction.java:434)
	at org.python.core.PyMethod.__call__(PyMethod.java:156)
	at SocketServer$py.process_request_thread$36(SocketServer.py:605)
	at SocketServer$py.call_function(SocketServer.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:308)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:199)
	at org.python.core.PyFunction.__call__(PyFunction.java:482)
	at org.python.core.PyMethod.instancemethod___call__(PyMethod.java:237)
	at org.python.core.PyMethod.__call__(PyMethod.java:228)
	at org.python.core.PyMethod.__call__(PyMethod.java:223)
	at org.python.core.PyObject._callextra(PyObject.java:620)
	at threading$py.run$35(threading.py:213)
	at threading$py.call_function(threading.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:139)
	at org.python.core.PyFunction.__call__(PyFunction.java:413)
	at org.python.core.PyMethod.__call__(PyMethod.java:126)
	at threading$py._Thread__bootstrap$36(threading.py:266)
	at threading$py.call_function(threading.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:308)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:199)
	at org.python.core.PyFunction.__call__(PyFunction.java:482)
	at org.python.core.PyMethod.instancemethod___call__(PyMethod.java:237)
	at org.python.core.PyMethod.__call__(PyMethod.java:228)
	at org.python.core.PyMethod.__call__(PyMethod.java:218)
	at org.python.core.PyMethod.__call__(PyMethod.java:213)
	at org.python.core.FunctionThread.run(FunctionThread.java:25)
"MainThread":
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000000e0787518> (a java.util.concurrent.locks.ReentrantLock$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.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
	at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
	at org.python.modules._threading.RLock.RLock_acquire(RLock.java:42)
	at org.python.modules._threading.RLock$RLock_acquire_exposer.__call__(Unknown Source)
	at org.python.core.PyObject.__call__(PyObject.java:468)
	at logging$py._acquireLock$6(logging/__init__.py:219)
	at logging$py.call_function(logging/__init__.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:125)
	at org.python.core.PyFunction.__call__(PyFunction.java:403)
	at logging.config$py.stopListening$48(logging/config.py:906)
	at logging.config$py.call_function(logging/config.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:125)
	at org.python.core.PyFunction.__call__(PyFunction.java:403)
	at test.test_logging$py.setup_via_listener$84(test/test_logging.py:1809)
	at test.test_logging$py.call_function(test/test_logging.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:154)
	at org.python.core.PyFunction.__call__(PyFunction.java:423)
	at org.python.core.PyMethod.__call__(PyMethod.java:141)
	at test.test_logging$py.test_listen_config_10_ok$85(test/test_logging.py:1825)
	at test.test_logging$py.call_function(test/test_logging.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:139)
	at org.python.core.PyFunction.__call__(PyFunction.java:413)
	at org.python.core.PyMethod.__call__(PyMethod.java:126)
	at unittest.case$py.run$35(unittest/case.py:377)
	at unittest.case$py.call_function(unittest/case.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:308)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:199)
	at org.python.core.PyFunction.__call__(PyFunction.java:482)
	at org.python.core.PyMethod.instancemethod___call__(PyMethod.java:237)
	at org.python.core.PyMethod.__call__(PyMethod.java:228)
	at org.python.core.PyMethod.__call__(PyMethod.java:223)
	at org.python.core.PyObject._callextra(PyObject.java:620)
	at unittest.case$py.__call__$37(unittest/case.py:396)
	at unittest.case$py.call_function(unittest/case.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:308)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:199)
	at org.python.core.PyFunction.__call__(PyFunction.java:482)
	at org.python.core.PyMethod.instancemethod___call__(PyMethod.java:237)
	at org.python.core.PyMethod.__call__(PyMethod.java:228)
	at org.python.core.PyMethod.__call__(PyMethod.java:223)
	at org.python.core.PyObjectDerived.__call__(PyObjectDerived.java:1030)
	at org.python.core.PyObject.__call__(PyObject.java:480)
	at org.python.core.PyObject.__call__(PyObject.java:484)
	at unittest.suite$py.run$16(unittest/suite.py:116)
	at unittest.suite$py.call_function(unittest/suite.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:308)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:199)
	at org.python.core.PyFunction.__call__(PyFunction.java:482)
	at org.python.core.PyMethod.instancemethod___call__(PyMethod.java:237)
	at org.python.core.PyMethod.__call__(PyMethod.java:228)
	at org.python.core.PyMethod.__call__(PyMethod.java:223)
	at org.python.core.PyObject._callextra(PyObject.java:620)
	at unittest.suite$py.__call__$13(unittest/suite.py:70)
	at unittest.suite$py.call_function(unittest/suite.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:308)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:199)
	at org.python.core.PyFunction.__call__(PyFunction.java:482)
	at org.python.core.PyMethod.instancemethod___call__(PyMethod.java:237)
	at org.python.core.PyMethod.__call__(PyMethod.java:228)
	at org.python.core.PyMethod.__call__(PyMethod.java:223)
	at org.python.core.PyObjectDerived.__call__(PyObjectDerived.java:1030)
	at org.python.core.PyObject.__call__(PyObject.java:480)
	at org.python.core.PyObject.__call__(PyObject.java:484)
	at unittest.suite$py.run$16(unittest/suite.py:116)
	at unittest.suite$py.call_function(unittest/suite.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:308)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:199)
	at org.python.core.PyFunction.__call__(PyFunction.java:482)
	at org.python.core.PyMethod.instancemethod___call__(PyMethod.java:237)
	at org.python.core.PyMethod.__call__(PyMethod.java:228)
	at org.python.core.PyMethod.__call__(PyMethod.java:223)
	at org.python.core.PyObject._callextra(PyObject.java:620)
	at unittest.suite$py.__call__$13(unittest/suite.py:70)
	at unittest.suite$py.call_function(unittest/suite.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:308)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:199)
	at org.python.core.PyFunction.__call__(PyFunction.java:482)
	at org.python.core.PyMethod.instancemethod___call__(PyMethod.java:237)
	at org.python.core.PyMethod.__call__(PyMethod.java:228)
	at org.python.core.PyMethod.__call__(PyMethod.java:223)
	at org.python.core.PyObjectDerived.__call__(PyObjectDerived.java:1030)
	at org.python.core.PyObject.__call__(PyObject.java:480)
	at org.python.core.PyObject.__call__(PyObject.java:484)
	at test.junit_xml$py.run$3(test/junit_xml.py:27)
	at test.junit_xml$py.call_function(test/junit_xml.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:154)
	at org.python.core.PyFunction.__call__(PyFunction.java:423)
	at org.python.core.PyMethod.__call__(PyMethod.java:141)
	at test.test_support$py._run_suite$102(test/test_support.py:1303)
	at test.test_support$py.call_function(test/test_support.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:308)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:132)
	at org.python.core.PyFunction.__call__(PyFunction.java:413)
	at test.test_support$py.run_unittest$103(test/test_support.py:1320)
	at test.test_support$py.call_function(test/test_support.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:308)
	at org.python.core.PyFunction.function___call__(PyFunction.java:471)
	at org.python.core.PyFunction.__call__(PyFunction.java:466)
	at org.python.core.PyFunction.__call__(PyFunction.java:456)
	at test.test_logging$py.test_main$96(test/test_logging.py:1927)
	at test.test_logging$py.call_function(test/test_logging.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:308)
	at org.python.core.PyFunction.function___call__(PyFunction.java:471)
	at org.python.core.PyFunction.__call__(PyFunction.java:466)
	at org.python.core.PyFunction.__call__(PyFunction.java:461)
	at org.python.core.PyObject._callextra(PyObject.java:620)
	at test.test_support$py.inner$83(test/test_support.py:1095)
	at test.test_support$py.call_function(test/test_support.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:308)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:119)
	at org.python.core.PyFunction.__call__(PyFunction.java:403)
	at org.python.pycode._pyx0.runtest_inner$5(test/regrtest.py:676)
	at org.python.pycode._pyx0.call_function(test/regrtest.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:308)
	at org.python.core.PyFunction.function___call__(PyFunction.java:471)
	at org.python.core.PyFunction.__call__(PyFunction.java:466)
	at org.python.core.PyFunction.__call__(PyFunction.java:456)
	at org.python.pycode._pyx0.runtest$4(test/regrtest.py:566)
	at org.python.pycode._pyx0.call_function(test/regrtest.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:308)
	at org.python.core.PyFunction.function___call__(PyFunction.java:471)
	at org.python.core.PyFunction.__call__(PyFunction.java:466)
	at org.python.core.PyFunction.__call__(PyFunction.java:456)
	at org.python.pycode._pyx0.main$2(test/regrtest.py:503)
	at org.python.pycode._pyx0.call_function(test/regrtest.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:308)
	at org.python.core.PyBaseCode.call(PyBaseCode.java:119)
	at org.python.core.PyFunction.__call__(PyFunction.java:403)
	at org.python.pycode._pyx0.f$0(test/regrtest.py:1558)
	at org.python.pycode._pyx0.call_function(test/regrtest.py)
	at org.python.core.PyTableCode.call(PyTableCode.java:167)
	at org.python.core.PyCode.call(PyCode.java:18)
	at org.python.core.Py.runCode(Py.java:1401)
	at org.python.util.PythonInterpreter.execfile(PythonInterpreter.java:296)
	at org.python.util.jython.run(jython.java:362)
	at org.python.util.jython.main(jython.java:142)

Found 1 deadlock.
History
Date User Action Args
2016-12-01 14:43:27stefan.richthofercreate