homepage

Builds:
* 52: build interrupted after 132 hours
* 53: test_ttk_guionly passed
* 54: test_ttk_guionly passed
* 55: build interrupted after 14 hours
Example:
http://buildbot.python.org/all/builders/AMD64%20Windows8.1%20Refleaks%202.7/builds/52/steps/test/logs/stdio
...
running: test_ttk_guionly (472605 sec)
running: test_ttk_guionly (472635 sec)
running: test_ttk_g
command interrupted, attempting to kill
program finished with exit code 1
elapsedTime=475847.190000

I interrupted the build 61 (it was running since 58 hours).
...
running: test_ttk_guionly (191065 sec)
running: test_ttk_guionly (191095 s
command interrupted, attempting to kill

The build 56 was also interrupted, it was running for 85 hours.

The build 43 was also interrupted (it was running for 10 hours).
Summary on builds 42-61, builds interrupted because of test_ttk_guionly: 43, 52, 55, 56, 61.
Note: build 53 also failed, but for a different unknown reason.

> Summary on builds 42-61, builds interrupted because of test_ttk_guionly: 43, 52, 55, 56, 61.
5 fails/20 builds: a failure rate of 25% (1/4) :-(

I'm trying to reproduce the bug using the following command run in a Command Prompt:
PCbuild\amd64\python_d.exe -m test -r -u all -R 3:3 -F -v --timeout=30 test_ttk_guionly
Note: I'm using https://github.com/python/cpython/pull/3019 to get --timeout feature.
Once (when I wasn't using --timeout=30), I saw test_ttk.test_widgets.TreeviewTest.test_tag_bind() stuck! But it only saw this bug twice in 1 hour of intensive tests, and so I'm not sure that it exists.
Since I unable to easily reproduce the bug, it's hard to collect more information about the program state when the bug occurs.

Ah! I captured the traceback of a first bug using the command:
PCbuild\amd64\python_d.exe -m test -R 3:3 -u all -v --timeout=30 -r -F test_ttk_guionly
Output:
(...)
test_resize (test_ttk.test_extensions.LabeledScaleTest) ...
*** STACKTRACE - START ***
# ThreadID: 1216
File: "C:\haypo2円.7\lib\threading.py", line 774, in __bootstrap
 self.__bootstrap_inner()
File: "C:\haypo2円.7\lib\threading.py", line 801, in __bootstrap_inner
 self.run()
File: "C:\haypo2円.7\lib\test\regrtest.py", line 2024, in run
 self.dump_threads()
File: "C:\haypo2円.7\lib\test\regrtest.py", line 2050, in dump_threads
 self.dump_thread(stack)
# ThreadID: 2172
File: "C:\haypo2円.7\lib\runpy.py", line 174, in _run_module_as_main
 "__main__", fname, loader, pkg_name)
File: "C:\haypo2円.7\lib\runpy.py", line 72, in _run_code
 exec code in run_globals
File: "C:\haypo2円.7\lib\test\__main__.py", line 3, in <module>
 regrtest.main_in_temp_cwd()
File: "C:\haypo2円.7\lib\test\regrtest.py", line 2083, in main_in_temp_cwd
 main()
File: "C:\haypo2円.7\lib\test\regrtest.py", line 841, in main
 result = local_runtest()
File: "C:\haypo2円.7\lib\test\regrtest.py", line 827, in local_runtest
 testdir=testdir)
File: "C:\haypo2円.7\lib\test\regrtest.py", line 1042, in runtest
 return runtest_inner(test, verbose, quiet, huntrleaks, pgo, testdir)
File: "C:\haypo2円.7\lib\test\regrtest.py", line 1234, in runtest_inner
 huntrleaks)
File: "C:\haypo2円.7\lib\test\regrtest.py", line 1369, in dash_R
 run_the_test()
File: "C:\haypo2円.7\lib\test\regrtest.py", line 1355, in run_the_test
 indirect_test()
File: "C:\haypo2円.7\lib\test\test_ttk_guionly.py", line 37, in test_main
 *runtktests.get_tests(text=False, packages=['test_ttk']))
File: "C:\haypo2円.7\lib\test\support\__init__.py", line 1577, in run_unittest
 _run_suite(suite)
File: "C:\haypo2円.7\lib\test\support\__init__.py", line 1532, in _run_suite
 result = runner.run(suite)
File: "C:\haypo2円.7\lib\unittest\runner.py", line 151, in run
 test(result)
File: "C:\haypo2円.7\lib\unittest\suite.py", line 70, in __call__
 return self.run(*args, **kwds)
File: "C:\haypo2円.7\lib\unittest\suite.py", line 108, in run
 test(result)
File: "C:\haypo2円.7\lib\unittest\suite.py", line 70, in __call__
 return self.run(*args, **kwds)
File: "C:\haypo2円.7\lib\unittest\suite.py", line 108, in run
 test(result)
File: "C:\haypo2円.7\lib\unittest\case.py", line 393, in __call__
 return self.run(*args, **kwds)
File: "C:\haypo2円.7\lib\unittest\case.py", line 329, in run
 testMethod()
File: "C:\haypo2円.7\lib\lib-tk\test\test_ttk\test_extensions.py", line 184, in t
est_resize
 x.update()
File: "C:\haypo2円.7\lib\lib-tk\Tkinter.py", line 1023, in update
 self.tk.call('update')
*** STACKTRACE - END ***

Another bug, truncated traceback since the top was the same:
(...)
File: "C:\haypo2円.7\lib\lib-tk\test\test_ttk\test_widgets.py", line 1367, in test_heading_callback
 self.tv.update()
File: "C:\haypo2円.7\lib\lib-tk\Tkinter.py", line 1023, in update
 self.tk.call('update')

I created bpo-31135: "[2.7] test_ttk_guionly doesn't destroy all widgets on Python 2.7".

Calling "self.tk.call('update')" runs the Tcl event loop:
* http://wiki.tcl.tk/1252
* https://www.tcl.tk/man/tcl/TclCmd/update.htm
Interesting but very old (2001) article: "Update considered harmful"
http://wiki.tcl.tk/1255 

The Tcl event loop is recursive: http://wiki.tcl.tk/1527 

Yesterday, I ran test_ttk_guionly during 3 hours on Windows with Python 2.7 compiled in debug mode. I saw between 4 and 7 hangs. I'm not sure about the exact number since sometimes the test unblocked when I just moved my mouse or clicked on my Command Prompt window....
At this point, I'm only sure that the following tests blocked:
* test_ttk\test_extensions.py:184: LabeledScaleTest.test_resize() -- test ttk.LabeledScale
* test_ttk\test_widgets.py:1367: TreeviewTest.test_heading_callback() -- test ttk.Treeview
* test_ttk.test_widgets.TreeviewTest.test_tag_bind() -- test ttk.Treeview
bpo-31135 fixes LabeledScale.destroy(), so it may be related.

Another hang: test_ttk\test_extensions.py:335: LabeledScaleTest.test2_variable_change(). Traceback:
(...)
File: "C:\haypo2円.7\lib\lib-tk\test\test_ttk\test_extensions.py", line 335, in test2_variable_change
 x.update()
File: "C:\haypo2円.7\lib\lib-tk\Tkinter.py", line 1023, in update
 self.tk.call('update')
I'm now using this batch script:
---
:repeat
PCbuild\amd64\python_d.exe -m test -u all --timeout=30 -R 3:3 -r test_ttk_guionly
if not %errorlevel% equ 0 goto :fail
echo OKKKKK
goto :repeat
:fail
echo ERRRRRR
---

I pushed my fix for bpo-31135, no idea at this point if it fix this issue.
New changeset 56e162ad5c5d3effe9b4f05d0179e1b6a2a2d9b8 by Victor Stinner in branch '2.7':
ttk: fix LabeledScale and OptionMenu destroy() method (#3026)
https://github.com/python/cpython/commit/56e162ad5c5d3effe9b4f05d0179e1b6a2a2d9b8 

I interrupted http://buildbot.python.org/all/builders/AMD64%20Windows8.1%20Refleaks%202.7/builds/63/ which was running since 17 hours... ("running: test_ttk_guionly (32770 sec)")

> I pushed my fix for bpo-31135, no idea at this point if it fix this issue.
Too bad, test_resize() failed again while testing commit 56e162ad5c5d3effe9b4f05d0179e1b6a2a2d9b8 :-( So this fix was not enough.

> Too bad, test_resize() failed again while testing commit 56e162ad5c5d3effe9b4f05d0179e1b6a2a2d9b8 :-( So this fix was not enough.
I am not sure anymore about this statement. I had a bug in my watchdog code, that I fixed after this failure.
I ran again the test during 3 hours and it didn't fail.
I reverted all my local changes, I rebuild Python 2.7 in debug mode to get a fresh python_d.exe, I removed all __pycache__, and then I ran again the test during 1 hour: no fail. I ran 4 instances of the test in parallel during 1 hour: no fail.
Hum, it *seems* like the bug was fixed.
Since it's a race condition, it's not possible to say that it's really fixed. But my test results show that the bug is very likely to be fixed, so I close the bug.
I will watch AMD64 Windows8.1 Refleaks 2.7 buildbot slave next days to check if the bug occurs again.