'hgtk log' sometimes leave a frozen process on close

[Flávio Etrusco]

How to reproduce:
- create new file in the repository:
   touch newfile
- schedule the new file for commit
   hg addremove
- start hgtk commit
   hgtk ci
- add a comment and commit using the GUI
- exit hgtk

Expected Result:
-hgtk terminates

Actual Result:
-hgtk does not terminate
-Ctrl-C does not terminate it

This happens with python2.6 (also on Debian unstable), but does not happen with python2.5.
Still present with tortoisehg 0.9.3-1.

The hgtk code tries to exit by raising a SystemExit exception, but the process never terminates. Adding an explicit sys.exit() does not change the described behavior.

Attaching to the dangling process with pdb shows:
https://bugs.edge.launchpad.net/ubuntu/+source/tortoisehg/+bug/519984/comments/15

Backtrace using GDB (2 threads):
#0 sem_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/sem_wait.S:85
#1 0x00000000004cf048 in PyThread_acquire_lock (lock=0x109b720, waitflag=0x80) at ../Python/thread_pthread.h:349
#2 0x00000000004d22f2 in lock_PyThread_acquire_lock (self=0xd326d8, args=<value optimized out>) at ../Modules/threadmodule.c:46
#3 0x00000000004a435d in call_function (f=0x16f38c0, throwflag=<value optimized out>) at ../Python/ceval.c:3728
#4 PyEval_EvalFrameEx (f=0x16f38c0, throwflag=<value optimized out>) at ../Python/ceval.c:2411
#5 0x00000000004a5b30 in PyEval_EvalCodeEx (co=0x1172198, globals=<value optimized out>, locals=<value optimized out>, args=0x2, argcount=<value optimized out>, kws=<value optimized out>, kwcount=0x0, defs=0x16bc668, defcount=0x1, closure=0x0) at ../Python/ceval.c:2990
#6 0x00000000004a3eaf in fast_function (f=0x15dd820, throwflag=<value optimized out>) at ../Python/ceval.c:3824
#7 call_function (f=0x15dd820, throwflag=<value optimized out>) at ../Python/ceval.c:3749
#8 PyEval_EvalFrameEx (f=0x15dd820, throwflag=<value optimized out>) at ../Python/ceval.c:2411
#9 0x00000000004a5b30 in PyEval_EvalCodeEx (co=0x16ad3f0, globals=<value optimized out>, locals=<value optimized out>, args=0x2, argcount=<value optimized out>, kws=<value optimized out>, kwcount=0x0, defs=0x116a6e8, defcount=0x1, closure=0x0) at ../Python/ceval.c:2990
#10 0x00000000004a3eaf in fast_function (f=0x17d0120, throwflag=<value optimized out>) at ../Python/ceval.c:3824
#11 call_function (f=0x17d0120, throwflag=<value optimized out>) at ../Python/ceval.c:3749
#12 PyEval_EvalFrameEx (f=0x17d0120, throwflag=<value optimized out>) at ../Python/ceval.c:2411
#13 0x00000000004a5b30 in PyEval_EvalCodeEx (co=0x16adeb8, globals=<value optimized out>, locals=<value optimized out>, args=0x1, argcount=<value optimized out>, kws=<value optimized out>, kwcount=0x0, defs=0x0, defcount=0x0, closure=0x0) at ../Python/ceval.c:2990
#14 0x0000000000530ab0 in function_call (func=0x16c1140, arg=0x7f372abf9850, kw=0x0) at ../Objects/funcobject.c:524
#15 0x000000000041efd7 in PyObject_Call (func=0x16c1140, arg=0x80, kw=0x0) at ../Objects/abstract.c:2492
#16 0x0000000000426d9f in instancemethod_call (func=0x16c1140, arg=0x7f372abf9850, kw=0x0) at ../Objects/classobject.c:2579
#17 0x0000000000420519 in PyObject_Call (func=0x113b460, arg=0x80, kw=<value optimized out>) at ../Objects/abstract.c:2492
#18 0x0000000000424083 in call_function_tail (o=<value optimized out>, name=<value optimized out>, format=<value optimized out>) at ../Objects/abstract.c:2524
#19 PyObject_CallMethod (o=<value optimized out>, name=<value optimized out>, format=<value optimized out>) at ../Objects/abstract.c:2601
#20 0x00000000004c4749 in wait_for_thread_shutdown () at ../Python/pythonrun.c:1687
#21 Py_Finalize () at ../Python/pythonrun.c:392
#22 0x00000000004c4223 in Py_Exit () at ../Python/pythonrun.c:1744
#23 handle_system_exit () at ../Python/pythonrun.c:1120
#24 0x00000000004c4445 in PyErr_PrintEx (set_sys_last_vars=0x1) at ../Python/pythonrun.c:1130
#25 0x00000000004c5280 in PyRun_SimpleFileExFlags (fp=<value optimized out>, filename=0x7fff2c51f5c7 "/usr/bin/hgtk", closeit=0x1, flags=0x7fff2c51ef80) at ../Python/pythonrun.c:939
#26 0x000000000041a467 in Py_Main (argc=0x2ab88080, argv=<value optimized out>) at ../Modules/main.c:572
#27 0x00007f3729698abd in __libc_start_main (main=<value optimized out>, argc=<value optimized out>, ubp_av=<value optimized out>, init=<value optimized out>, fini=<value optimized out>, rtld_fini=<value optimized out>, stack_end=0x7fff2c51f098) at libc-start.c:222
#28 0x0000000000419749 in _start ()

#0 0x00007f372a86c90b in read () from /lib/libpthread.so.0
#1 0x000000000050f648 in posix_read (self=<value optimized out>, args=<value optimized out>) at ../Modules/posixmodule.c:6423
#2 0x00000000004a435d in call_function (f=0x17b3280, throwflag=<value optimized out>) at ../Python/ceval.c:3728
#3 PyEval_EvalFrameEx (f=0x17b3280, throwflag=<value optimized out>) at ../Python/ceval.c:2411
#4 0x00000000004a5b30 in PyEval_EvalCodeEx (co=0x16e9468, globals=<value optimized out>, locals=<value optimized out>, args=0x0, argcount=<value optimized out>, kws=<value optimized out>, kwcount=0x0, defs=0x0, defcount=0x0, closure=0x16ea050) at ../Python/ceval.c:2990
#5 0x0000000000530bad in function_call (func=0x16e55f0, arg=0x7f372ac30050, kw=0x17a8d60) at ../Objects/funcobject.c:524
#6 0x000000000041efd7 in PyObject_Call (func=0x16e55f0, arg=0x17ba734, kw=0x400) at ../Objects/abstract.c:2492
#7 0x00000000004a2981 in ext_do_call (f=0x16f85e0, throwflag=<value optimized out>) at ../Python/ceval.c:4041
#8 PyEval_EvalFrameEx (f=0x16f85e0, throwflag=<value optimized out>) at ../Python/ceval.c:2451
#9 0x00000000004a4897 in fast_function (f=0x16f8380, throwflag=<value optimized out>) at ../Python/ceval.c:3814
#10 call_function (f=0x16f8380, throwflag=<value optimized out>) at ../Python/ceval.c:3749
#11 PyEval_EvalFrameEx (f=0x16f8380, throwflag=<value optimized out>) at ../Python/ceval.c:2411
#12 0x00000000004a4897 in fast_function (f=0x16ecbf0, throwflag=<value optimized out>) at ../Python/ceval.c:3814
#13 call_function (f=0x16ecbf0, throwflag=<value optimized out>) at ../Python/ceval.c:3749
#14 PyEval_EvalFrameEx (f=0x16ecbf0, throwflag=<value optimized out>) at ../Python/ceval.c:2411
#15 0x00000000004a5b30 in PyEval_EvalCodeEx (co=0x16ad0a8, globals=<value optimized out>, locals=<value optimized out>, args=0x1, argcount=<value optimized out>, kws=<value optimized out>, kwcount=0x0, defs=0x0, defcount=0x0, closure=0x0) at ../Python/ceval.c:2990
#16 0x0000000000530ab0 in function_call (func=0x16c0668, arg=0x116a5d0, kw=0x0) at ../Objects/funcobject.c:524
#17 0x000000000041efd7 in PyObject_Call (func=0x16c0668, arg=0x17ba734, kw=0x400) at ../Objects/abstract.c:2492
#18 0x0000000000426d9f in instancemethod_call (func=0x16c0668, arg=0x116a5d0, kw=0x0) at ../Objects/classobject.c:2579
#19 0x000000000041efd7 in PyObject_Call (func=0x115faf0, arg=0x17ba734, kw=0x400) at ../Objects/abstract.c:2492
#20 0x000000000049e093 in PyEval_CallObjectWithKeywords (func=0x115faf0, arg=0x7f372ac30050, kw=0x400) at ../Python/ceval.c:3597
#21 0x00000000004d26fd in t_bootstrap (boot_raw=0x1779c70) at ../Modules/threadmodule.c:425
#22 0x00007f372a86573a in start_thread (arg=<value optimized out>) at pthread_create.c:300
#23 0x00007f37297456dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#24 0x0000000000000000 in ?? ()

Note that it deadlock inside the call to Py_Exit(), so it appears to be realted to some resource release code.

ProblemType: Bug
Architecture: i386
Date: Wed Feb 10 14:55:06 2010
DistroRelease: Ubuntu 10.04
EcryptfsInUse: Yes
ExecutablePath: /usr/bin/hgtk
InterpreterPath: /usr/bin/python2.6
Package: tortoisehg 0.9.2-1
PackageArchitecture: all
ProcEnviron:
 SHELL=/bin/bash
 LANG=en_US.UTF-8
ProcVersionSignature: Ubuntu 2.6.32-12.17-generic
SourcePackage: tortoisehg
Uname: Linux 2.6.32-12-generic i686

[Ludovico Cavedon (cavedon)]

Thank you for taking the time to report the problem.
It would be very useful if you could get a dump of the python call stack. You can do that in this way
-start hgtk log with
 hgtk log --nofork --debugger
-the debugger will start write "c" and press return
-the hgtk window will appear; do whatever you think might trigger the bug
-close the hgtk window; if the process does not terminate, you should not get the prompt tat the terminal
-hit CTRL-C
-give the "bt" command
-copy the output and paste it here

Thank you!
Ludovico

[Flávio Etrusco (etrusco)]

Thanks for your help, I'll try that!
The problem is that when that happens I can't Ctrl+C in the terminal.
Seems both hgtk and python processes are stuck in a futex (don't know
whether it's the same. Hmm, I had a tool to debug futexes
somewhere...).

[Ludovico Cavedon (cavedon)]

mhm, if CTRL-C does not work, that it would be better to get a low level stack trace.
You can get that by installing python-dbg, adn attaching to the process with gdb
  gdb python PID
where PID is the process ID of the python process executing hgtk

[Flávio Etrusco (etrusco)]

Guess the trace won't be as useful as I tought.
Anyway, I could trigger deadlock by just:
1) hgtk log
2) Check Incoming (nothing received).
3) qgoto to the 4th os my mq patches (using the hgtk log interface).
4) Open Commit command. Click Refresh view.
5) Close Commit dialog, close Log dialog.

[Flávio Etrusco (etrusco)]

Also, I don't know whether it was effect of the pythong debugging (I started the command as you suggested, and being unnable to Ctrl+C attached gdb) or whether it was simply a timeout, but I left the thing untouched for some time doing other stuff and then the python process that seemed to be deadlocked (in a futex_wait too) terminated (and in zombie state).

[Ludovico Cavedon (cavedon)]

Yes, the process is still in the python eval loop, so the gdb backtrace is not very useful.
Thank you though.
It would be useful to inspect it with pdb, but I do not know how to get there.

Maybe strace could give some useful output, we should be able to see on what it locked
   strace hgtk log --no-fork

[Flávio Etrusco (etrusco)]

Is it really useful that I report these errors here? (Even if they had the relevant information ;-) I've noticed that upstream is already at version 0.9.3.
Do you believe this (or some later) version will still get into Lucid?

[Ludovico Cavedon (cavedon)]

0.9.3 it not a big change, I believe it is not changing the behavior of your problem. However you are right.
You can install 0.9.3 from debian unstable directly. If it fixes your issue, we can ask for a sync.
Thanks

[Flávio Etrusco (etrusco)]

No luck. The Debian package depends on python < 2.6 and (installed with --force-all) seem to have installed files in the 2.5 libraries, but even installing python 2.5 doesn't satisfy it :-/ strace it is...
Thanks.

[Ludovico Cavedon (cavedon)]

Mhm, sorry, I forgot that lucid has no python 2.5.
I uploaded a version for lucid on my PPA:
https://edge.launchpad.net/~cavedon/+archive/ppa

[Flávio Etrusco (etrusco)]

Thanks a lot! Too bad it didn't work :-/
I'll try winpdb to get a stacktrace of the python script/program instead, as I guess the problem is there...

[Flávio Etrusco (etrusco)]

Unless this is related to the use of python 2.6... I was thinking about setting up a debian partition anyway ;-)

[Ludovico Cavedon (cavedon)]

I was suspecting something depeninf on python 2.6. I tried to build it on debian unstable against python2.6, but I was not able to reproduce the problem :(

[Flávio Etrusco (etrusco)]

Do you mean you're able to reproduce it on Ubuntu? ;)
I hadn't much luck with winpdb either. The process has two threads stuck at line 121 of hgcmd.py (in your 0.9.3 package):

    def _on_window_map_event(self, event, param):
        if self.hgthread:
            return

        # Replace stdout file descriptor with our own pipe
        def pollstdout(*args):
            while True:
                # blocking read of stdout pipe
--> o = os.read(self.readfd, 1024)
              else:
                    break
        self.oldstdout = os.dup(sys.__stdout__.fileno())

But I couldn't make winpdb to Stp Out (or Jump to the right line) nor discovered where readfd should be written...
Thanks again for your time.

[Flávio Etrusco (etrusco)]

(Well, you can see the code was a bit chopped, but the mark is correct nevertheless)
I found a simple and 100% reproducible test-case: in a repository with mq enabled and a patch applied, invoke 'hgtk ci' and click 'refresh top MQ patch' (which in normal operation is the 'commit' action).

I seem to have find a related upstream bug BTW: http://bitbucket.org/tortoisehg/stable/issue/783/commit-process-does-not-terminate-when-i-close-the-gui-after

[Ludovico Cavedon (cavedon)]

I tried to reproduce the bug on karmic and on debian unstable with python 2.6. Actually I do not have a lucid chroot. I'll try to make one.
Thank for the test win winpdb.

[Ludovico Cavedon (cavedon)]

Confirming the bug and editing description

[Ludovico Cavedon (cavedon)]

Upstream bug: http://bitbucket.org/tortoisehg/stable/issue/783
Appears to have just been fixed by upstream.

[Ludovico Cavedon (cavedon)]

backported fix from debian

[Chow Loong Jin (hyperair)]

Sponsored.