classification
Title: [2.7] test_ttk_guionly hangs at self.tk.call('update') on AMD64 Windows8.1 Refleaks 2.7
Type: Stage: resolved
Components: Tests, Tkinter Versions: Python 2.7
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: gpolo, haypo, serhiy.storchaka
Priority: normal Keywords:

Created on 2017-07-28 14:59 by haypo, last changed 2017-08-08 23:50 by haypo. This issue is now closed.

Messages (17)
msg299391 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-07-28 14:59
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
msg299841 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-08-07 10:24
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
msg299842 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-08-07 10:32
The build 56 was also interrupted, it was running for 85 hours.
msg299843 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-08-07 10:35
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.
msg299844 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-08-07 10:36
> 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) :-(
msg299875 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-08-07 23:20
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.
msg299877 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-08-07 23:39
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 ***
msg299879 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-08-08 00:31
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')
msg299882 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-08-08 00:48
I created bpo-31135: "[2.7] test_ttk_guionly doesn't destroy all widgets on Python 2.7".
msg299919 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-08-08 13:31
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
msg299923 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-08-08 14:16
The Tcl event loop is recursive: http://wiki.tcl.tk/1527
msg299928 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-08-08 14:47
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.
msg299930 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-08-08 15:14
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
---
msg299941 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-08-08 17:42
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
msg299943 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-08-08 17:50
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)")
msg299944 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-08-08 17:52
> 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.
msg299954 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2017-08-08 23:50
> 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.
History
Date User Action Args
2017-08-08 23:50:44hayposetstatus: open -> closed
resolution: fixed
messages: + msg299954

stage: resolved
2017-08-08 17:52:10hayposetmessages: + msg299944
2017-08-08 17:50:15hayposetmessages: + msg299943
2017-08-08 17:42:12hayposetmessages: + msg299941
2017-08-08 15:14:07hayposetmessages: + msg299930
2017-08-08 14:47:32hayposetmessages: + msg299928
2017-08-08 14:16:46hayposetmessages: + msg299923
2017-08-08 13:31:53hayposetmessages: + msg299919
title: test_ttk_guionly hangs at self.tk.call('update') on AMD64 Windows8.1 Refleaks 2.7 -> [2.7] test_ttk_guionly hangs at self.tk.call('update') on AMD64 Windows8.1 Refleaks 2.7
2017-08-08 01:28:44hayposetnosy: + gpolo
2017-08-08 00:50:31hayposettitle: test_ttk_guionly hangs on AMD64 Windows8.1 Refleaks 2.7 -> test_ttk_guionly hangs at self.tk.call('update') on AMD64 Windows8.1 Refleaks 2.7
2017-08-08 00:48:29hayposetnosy: + serhiy.storchaka
2017-08-08 00:48:19hayposetmessages: + msg299882
2017-08-08 00:31:09hayposetmessages: + msg299879
2017-08-07 23:39:46hayposetmessages: + msg299877
2017-08-07 23:20:12hayposetmessages: + msg299875
2017-08-07 10:36:20hayposetmessages: + msg299844
2017-08-07 10:35:24hayposetmessages: + msg299843
2017-08-07 10:32:04hayposetmessages: + msg299842
2017-08-07 10:24:39hayposetmessages: + msg299841
2017-07-28 14:59:47haypocreate