CI timed out while running tests

[chrstphrchvz]

I have only encountered this once, but would like to report this in case someone encounters it again.

This perl5.22.4-stretch CI run timed out after 6 hours: https://github.com/chrstphrchvz/perl-tk/actions/runs/7964546075/job/21742317875

I am not certain which test it was stuck on, but the only ones which had not completed were unicode.t, wm.t, and photo.t.

"/usr/local/bin/perl" "-It" "-MTkTest" "-e" "checked_test_harness('./xt', 0, 'blib/lib', 'blib/arch')" t/00wmcheck.t t/JP.t t/KR.t t/Require.t t/Tkxs.t t/Trace.t t/X.t t/adjuster.t t/after.t t/async.t t/autoload.t t/balloon.t t/bind.t t/browseentry-grabtest.t t/browseentry-subclassing.t t/browseentry.t t/browseentry2.t t/button-tcl.t t/button.t t/canvas-grid.t t/canvas.t t/canvas2.t t/coloreditor.t t/create.t t/cursor.t t/dash.t t/dialogbox.t t/dirtree.t t/entry.t t/errordialog.t t/eventGenerate.t t/exefiles.t t/fbox.t t/fileevent.t t/fileevent2.t t/fileselect.t t/font.t t/fork.t t/geomgr.t t/iso8859-1.t t/itemstyle.t t/leak.t t/list.t t/listbox.t t/listvar.t t/magic.t t/mega.t t/msgbox.t t/mwm.t t/notebook.t t/objglue.t t/optmenu.t t/photo.t t/pixmap.t t/pod.t t/progbar.t t/property.t t/regexp.t t/rotext.t t/slaves.t t/sv.t t/table.t t/text.t t/text2.t t/textundo.t t/trace1.t t/unicode.t t/widget.t t/wm-tcl.t t/wm-time.t t/wm.t t/zzHList.t t/zzPhoto.t t/zzScrolled.t t/zzText.t t/zzTixGrid.t
# 
# Tk platform:    unix
# server info:    X11R0 The X.Org Foundation 11902000
# window manager: <unknown>
#        version: <unknown>
# XFT:            yes
[19:51:49] t/00wmcheck.t ................ ok       20 ms ( 0.00 usr  0.00 sys +  0.06 cusr  0.01 csys =  0.07 CPU)
[19:51:49] t/bind.t ..................... ok       26 ms ( 0.00 usr  0.00 sys +  0.06 cusr  0.02 csys =  0.08 CPU)
[19:51:49] t/autoload.t ................. ok       61 ms ( 0.01 usr  0.01 sys +  0.18 cusr  0.06 csys =  0.26 CPU)
[19:51:49] t/balloon.t .................. ok       87 ms ( 0.00 usr  0.01 sys +  0.21 cusr  0.08 csys =  0.30 CPU)
[19:51:49] t/browseentry2.t ............. ok       29 ms ( 0.00 usr  0.00 sys +  0.06 cusr  0.02 csys =  0.08 CPU)
[19:51:49] t/browseentry.t .............. ok       98 ms ( 0.01 usr  0.00 sys +  0.25 cusr  0.08 csys =  0.34 CPU)
[19:51:49] t/button.t ................... ok       25 ms ( 0.01 usr  0.00 sys +  0.05 cusr  0.01 csys =  0.07 CPU)
[19:51:49] t/button-tcl.t ............... ok       91 ms ( 0.04 usr  0.00 sys +  0.28 cusr  0.06 csys =  0.38 CPU)
[19:51:49] t/after.t .................... ok      346 ms ( 0.06 usr  0.01 sys +  0.66 cusr  0.19 csys =  0.92 CPU)
[19:51:49] t/adjuster.t ................. ok      342 ms ( 0.07 usr  0.01 sys +  0.72 cusr  0.22 csys =  1.02 CPU)
[19:51:49] t/canvas.t ................... ok       80 ms ( 0.03 usr  0.00 sys +  0.17 cusr  0.04 csys =  0.24 CPU)
[19:51:49] t/canvas-grid.t .............. ok      206 ms ( 0.05 usr  0.01 sys +  0.41 cusr  0.10 csys =  0.57 CPU)
[19:51:49] t/async.t .................... ok      544 ms ( 0.12 usr  0.02 sys +  0.95 cusr  0.27 csys =  1.36 CPU)
[19:51:49] t/dash.t ..................... ok       19 ms ( 0.00 usr  0.00 sys +  0.05 cusr  0.02 csys =  0.07 CPU)
[19:51:49] t/browseentry-grabtest.t ..... ok      543 ms ( 0.12 usr  0.02 sys +  0.97 cusr  0.28 csys =  1.39 CPU)
[19:51:49] t/browseentry-subclassing.t .. ok      544 ms ( 0.13 usr  0.02 sys +  1.00 cusr  0.26 csys =  1.41 CPU)
[19:51:49] t/cursor.t ................... ok      210 ms ( 0.04 usr  0.03 sys +  0.39 cusr  0.11 csys =  0.57 CPU)
XS_Tk__Callback_Call error:Intentional error.

[19:51:49] t/eventGenerate.t ............ ok        0 ms ( 0.00 usr  0.00 sys +  0.07 cusr  0.01 csys =  0.08 CPU)
XS_Tk__Callback_Call error:Intentional error.

# <Expose> event did not arrive, wait for 1.08s...
[19:51:51] t/errordialog.t .............. ok     1162 ms ( 0.02 usr  0.00 sys +  0.15 cusr  0.03 csys =  0.20 CPU)
[19:51:51] t/canvas2.t .................. ok     1510 ms ( 0.08 usr  0.03 sys +  0.74 cusr  0.17 csys =  1.02 CPU)
[19:51:51] t/coloreditor.t .............. ok     1527 ms ( 0.09 usr  0.03 sys +  0.92 cusr  0.21 csys =  1.25 CPU)
[19:51:51] t/dirtree.t .................. ok     1239 ms ( 0.03 usr  0.01 sys +  0.73 cusr  0.16 csys =  0.93 CPU)
[19:51:51] t/dialogbox.t ................ ok     1342 ms ( 0.05 usr  0.01 sys +  0.96 cusr  0.21 csys =  1.23 CPU)
[19:51:51] t/create.t ................... ok     1572 ms ( 0.11 usr  0.03 sys +  1.61 cusr  0.33 csys =  2.08 CPU)
[19:51:51] t/entry.t .................... ok     1243 ms ( 0.05 usr  0.01 sys +  1.28 cusr  0.23 csys =  1.57 CPU)
[19:51:51] t/geomgr.t ................... ok      115 ms ( 0.01 usr  0.00 sys +  0.06 cusr  0.01 csys =  0.08 CPU)
Font Courier -12 still in cache.
[19:51:51] t/font.t ..................... ok       85 ms ( 0.01 usr  0.00 sys +  0.17 cusr  0.02 csys =  0.20 CPU)
[19:51:51] t/itemstyle.t ................ ok       11 ms ( 0.00 usr  0.00 sys +  0.06 cusr  0.02 csys =  0.08 CPU)
[19:51:51] t/fileselect.t ............... ok      289 ms ( 0.03 usr  0.00 sys +  0.55 cusr  0.08 csys =  0.66 CPU)
[19:51:51] t/fileevent2.t ............... ok      337 ms ( 0.05 usr  0.00 sys +  0.43 cusr  0.08 csys =  0.56 CPU)
[19:51:51] t/leak.t ..................... skipped: need Devel::Leak
[19:51:51] t/list.t ..................... ok        4 ms ( 0.00 usr  0.00 sys +  0.04 cusr  0.02 csys =  0.06 CPU)
[19:51:51] t/JP.t ....................... ok      307 ms ( 0.07 usr  0.02 sys +  0.24 cusr  0.09 csys =  0.42 CPU)
[19:51:51] t/KR.t ....................... ok      308 ms ( 0.07 usr  0.02 sys +  0.39 cusr  0.12 csys =  0.60 CPU)
[19:51:51] t/fork.t ..................... ok      530 ms ( 0.09 usr  0.03 sys +  0.83 cusr  0.19 csys =  1.14 CPU)
[19:51:51] t/magic.t .................... ok       18 ms ( 0.01 usr  0.00 sys +  0.05 cusr  0.01 csys =  0.07 CPU)
[19:51:51] t/mega.t ..................... ok       61 ms ( 0.02 usr  0.00 sys +  0.11 cusr  0.02 csys =  0.15 CPU)
[19:51:51] t/mwm.t ...................... ok        7 ms ( 0.01 usr  0.00 sys +  0.05 cusr  0.01 csys =  0.07 CPU)
[19:51:51] t/listbox.t .................. ok      230 ms ( 0.06 usr  0.01 sys +  0.65 cusr  0.16 csys =  0.88 CPU)
[19:51:51] t/objglue.t .................. ok        9 ms ( 0.00 usr  0.00 sys +  0.05 cusr  0.00 csys =  0.05 CPU)
[19:51:51] t/notebook.t ................. ok        5 ms ( 0.00 usr  0.00 sys +  0.07 cusr  0.02 csys =  0.09 CPU)
[19:51:52] t/optmenu.t .................. ok       50 ms ( 0.00 usr  0.00 sys +  0.05 cusr  0.02 csys =  0.07 CPU)
[19:51:52] t/fbox.t ..................... ok     1182 ms ( 0.16 usr  0.04 sys +  1.64 cusr  0.36 csys =  2.20 CPU)
[19:51:52] t/fileevent.t ................ ok     1137 ms ( 0.15 usr  0.04 sys +  1.57 cusr  0.36 csys =  2.12 CPU)
[19:51:52] t/pod.t ...................... skipped: Test::Pod 1.00 required for testing POD
[19:51:52] t/property.t ................. ok       15 ms ( 0.00 usr  0.00 sys +  0.04 cusr  0.00 csys =  0.04 CPU)
[19:51:52] t/progbar.t .................. ok       25 ms ( 0.00 usr  0.00 sys +  0.08 cusr  0.02 csys =  0.10 CPU)
[19:51:52] t/regexp.t ................... ok       47 ms ( 0.00 usr  0.00 sys +  0.12 cusr  0.04 csys =  0.16 CPU)
[19:51:52] t/rotext.t ................... ok       31 ms ( 0.00 usr  0.00 sys +  0.05 cusr  0.02 csys =  0.07 CPU)
[19:51:52] t/slaves.t ................... ok       10 ms ( 0.01 usr  0.00 sys +  0.03 cusr  0.01 csys =  0.05 CPU)
[19:51:52] t/Require.t .................. ok      127 ms ( 0.02 usr  0.01 sys +  0.26 cusr  0.07 csys =  0.36 CPU)
[19:51:52] t/pixmap.t ................... ok      513 ms ( 0.04 usr  0.02 sys +  0.77 cusr  0.15 csys =  0.98 CPU)
[19:51:52] t/sv.t ....................... ok       20 ms ( 0.00 usr  0.00 sys +  0.05 cusr  0.02 csys =  0.07 CPU)
untie attempted while 3 inner references still exist at t/text2.t line 59.
untie attempted while 10 inner references still exist at t/text2.t line 70.
[19:51:52] t/text2.t .................... ok       38 ms ( 0.01 usr  0.00 sys +  0.06 cusr  0.01 csys =  0.08 CPU)
Stack moved 55c4ca5c9ea0 => 55c4ca5c9ea8
[19:51:52] t/text.t ..................... ok      109 ms ( 0.04 usr  0.00 sys +  0.19 cusr  0.04 csys =  0.27 CPU)
[19:51:52] t/textundo.t ................. ok       27 ms ( 0.00 usr  0.00 sys +  0.19 cusr  0.04 csys =  0.23 CPU)
[19:51:52] t/table.t .................... ok      176 ms ( 0.04 usr  0.01 sys +  0.36 cusr  0.08 csys =  0.49 CPU)
[19:51:52] t/listvar.t .................. ok     1061 ms ( 0.14 usr  0.04 sys +  1.67 cusr  0.36 csys =  2.21 CPU)
[19:51:52] t/Tkxs.t ..................... ok        6 ms ( 0.00 usr  0.01 sys +  0.10 cusr  0.01 csys =  0.12 CPU)
[19:51:52] t/Trace.t .................... ok       19 ms ( 0.00 usr  0.00 sys +  0.06 cusr  0.02 csys =  0.08 CPU)
[19:51:52] t/widget.t ................... ok       47 ms ( 0.01 usr  0.00 sys +  0.06 cusr  0.02 csys =  0.09 CPU)
# Start update 2
# . update 0.00275 2
# .label update 0.00511 1
# Start Popup 2
# .toplevel Popup 0.00202 2
# .toplevel.label Popup 0.0026 1
# Start withdraw 0
# Start Popup Again 2
# .toplevel Popup Again 0.00246 2
# .toplevel.label Popup Again 0.00301 1
# Start destroy 0
[19:51:53] t/iso8859-1.t ................ ok     2172 ms ( 0.24 usr  0.09 sys +  2.49 cusr  0.61 csys =  3.43 CPU)
[19:51:53] t/msgbox.t ................... ok     1632 ms ( 0.13 usr  0.06 sys +  1.83 cusr  0.46 csys =  2.48 CPU)
[19:51:53] t/wm-time.t .................. ok      522 ms ( 0.01 usr  0.00 sys +  0.22 cusr  0.10 csys =  0.33 CPU)
[19:51:53] t/trace1.t ................... ok      677 ms ( 0.03 usr  0.01 sys +  0.40 cusr  0.16 csys =  0.60 CPU)
[19:51:53] t/X.t ........................ ok       46 ms ( 0.00 usr  0.00 sys +  0.10 cusr  0.03 csys =  0.13 CPU)
[19:51:53] t/zzPhoto.t .................. ok       34 ms ( 0.01 usr  0.00 sys +  0.04 cusr  0.03 csys =  0.08 CPU)
[19:51:53] t/zzHList.t .................. ok       46 ms ( 0.02 usr  0.00 sys +  0.11 cusr  0.05 csys =  0.18 CPU)
[19:51:53] t/zzScrolled.t ............... ok       53 ms ( 0.01 usr  0.01 sys +  0.08 cusr  0.02 csys =  0.12 CPU)
[19:51:53] t/zzText.t ................... ok       33 ms ( 0.01 usr  0.01 sys +  0.14 cusr  0.03 csys =  0.19 CPU)
[19:51:53] t/zzTixGrid.t ................ ok       19 ms ( 0.00 usr  0.00 sys +  0.21 cusr  0.03 csys =  0.24 CPU)
[19:51:54] t/wm-tcl.t ................... ok     1222 ms ( 0.06 usr  0.02 sys +  0.86 cusr  0.30 csys =  1.24 CPU)
[19:51:56] t/exefiles.t ................. ok     6558 ms ( 0.36 usr  0.11 sys +  5.03 cusr  1.22 csys =  6.72 CPU)
Error: The operation was canceled.

[chrstphrchvz]

Encountered again for perl:5.18.4-buster, but does not narrow down which test is stuck: https://github.com/chrstphrchvz/perl-tk/actions/runs/7981746848/job/21794034692