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:\haypo\2.7\lib\threading.py", line 774, in __bootstrap
  self.__bootstrap_inner()
File: "C:\haypo\2.7\lib\threading.py", line 801, in __bootstrap_inner
  self.run()
File: "C:\haypo\2.7\lib\test\regrtest.py", line 2024, in run
  self.dump_threads()
File: "C:\haypo\2.7\lib\test\regrtest.py", line 2050, in dump_threads
  self.dump_thread(stack)

# ThreadID: 2172
File: "C:\haypo\2.7\lib\runpy.py", line 174, in _run_module_as_main
  "__main__", fname, loader, pkg_name)
File: "C:\haypo\2.7\lib\runpy.py", line 72, in _run_code
  exec code in run_globals
File: "C:\haypo\2.7\lib\test\__main__.py", line 3, in <module>
  regrtest.main_in_temp_cwd()
File: "C:\haypo\2.7\lib\test\regrtest.py", line 2083, in main_in_temp_cwd
  main()
File: "C:\haypo\2.7\lib\test\regrtest.py", line 841, in main
  result = local_runtest()
File: "C:\haypo\2.7\lib\test\regrtest.py", line 827, in local_runtest
  testdir=testdir)
File: "C:\haypo\2.7\lib\test\regrtest.py", line 1042, in runtest
  return runtest_inner(test, verbose, quiet, huntrleaks, pgo, testdir)
File: "C:\haypo\2.7\lib\test\regrtest.py", line 1234, in runtest_inner
  huntrleaks)
File: "C:\haypo\2.7\lib\test\regrtest.py", line 1369, in dash_R
  run_the_test()
File: "C:\haypo\2.7\lib\test\regrtest.py", line 1355, in run_the_test
  indirect_test()
File: "C:\haypo\2.7\lib\test\test_ttk_guionly.py", line 37, in test_main
  *runtktests.get_tests(text=False, packages=['test_ttk']))
File: "C:\haypo\2.7\lib\test\support\__init__.py", line 1577, in run_unittest
  _run_suite(suite)
File: "C:\haypo\2.7\lib\test\support\__init__.py", line 1532, in _run_suite
  result = runner.run(suite)
File: "C:\haypo\2.7\lib\unittest\runner.py", line 151, in run
  test(result)
File: "C:\haypo\2.7\lib\unittest\suite.py", line 70, in __call__
  return self.run(*args, **kwds)
File: "C:\haypo\2.7\lib\unittest\suite.py", line 108, in run
  test(result)
File: "C:\haypo\2.7\lib\unittest\suite.py", line 70, in __call__
  return self.run(*args, **kwds)
File: "C:\haypo\2.7\lib\unittest\suite.py", line 108, in run
  test(result)
File: "C:\haypo\2.7\lib\unittest\case.py", line 393, in __call__
  return self.run(*args, **kwds)
File: "C:\haypo\2.7\lib\unittest\case.py", line 329, in run
  testMethod()
File: "C:\haypo\2.7\lib\lib-tk\test\test_ttk\test_extensions.py", line 184, in t
est_resize
  x.update()
File: "C:\haypo\2.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:\haypo\2.7\lib\lib-tk\test\test_ttk\test_widgets.py", line 1367, in test_heading_callback
  self.tv.update()
File: "C:\haypo\2.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:\haypo\2.7\lib\lib-tk\test\test_ttk\test_extensions.py", line 335, in test2_variable_change
  x.update()
File: "C:\haypo\2.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.