TortoiseOverlayServer started by msiexec cannot exit cleanly

Issue #140 resolved
Steve Borho
created an issue

The process gets stuck somehow at exit, leaving a zombie that has to be closed by hand.

Comments (27)

  1. Adrian Buehlmann

    With the two patches now pushed as 1bbc20accd98, then building an x64 msi, installing it on Windows 7 SP1 x64 and then terminating the overlay server from the taskbar cmenu, I see in C:\Users\adi\AppData\Roaming\TortoiseHg\OverlayServerLog.txt:

    [02/24/11 00:40:03] TortoiseHg Overlay Icon Server, Version 1.9.3+133-4e8ae5ff6ad0
    [02/24/11 00:40:03] Logging to file started
    [02/24/11 00:40:54] Stopping pipe server...
    [02/24/11 00:40:54] PipeServer thread terminating
    [02/24/11 00:40:54] Updater thread terminating
    [02/24/11 00:40:54] Traceback (most recent call last):
      File "TortoiseHgOverlayServer.py", line 198, in stop_pipe_server
      File "tortoisehg\util\thread2.pyo", line 52, in terminate
      File "tortoisehg\util\thread2.pyo", line 47, in raise_exc
      File "tortoisehg\util\thread2.pyo", line 19, in _async_raise
    ValueError: invalid thread id
    
    [02/24/11 00:40:54] Goodbye
    
  2. Adrian Buehlmann

    Back to the issue: I think that traceback isn't a problem. The thread most likely just has already terminated.

    I'm still puzzled what the problem could be. Needs more investigation...

  3. Adrian Buehlmann

    Perhaps I'm going to try

    diff --git a/TortoiseHgOverlayServer.py b/TortoiseHgOverlayServer.py
    --- a/TortoiseHgOverlayServer.py
    +++ b/TortoiseHgOverlayServer.py
    @@ -195,8 +195,8 @@ class MainWindow:
             while cnt <= max_try and self.pipethread.isAlive():
                 print "testing pipe [try %d] ..." % cnt
                 try:
    +                win32pipe.CallNamedPipe(PIPENAME, '', PIPEBUFSIZE, 0)
                     self.pipethread.terminate()
    -                win32pipe.CallNamedPipe(PIPENAME, '', PIPEBUFSIZE, 0)
                 except:
                     logger.msg(traceback.format_exc())
                     pass
    
    

    tomorrow. I'm running out of time here.

  4. Steve Borho reporter

    I thought you had attached patches for the overlay server, but that was for the ctypes issue. I didn't expect to have to pull changes because I had just pushed a couple minutes earlier without any warnings. No big deal.

    I agree the traceback is most likely harmless, just a timing quirk.

    How about this theory: DestroyWindow() is ignored because of access privileges and the process just stays open.

  5. Adrian Buehlmann

    Well, I wrote "With the two patches now pushed as 1bbc20accd98", guess who pushed them? :-)

    Sorry for the surprise, but after all, it was you who blessed me again with push rights.

    Let me know if you want me to warn/patchbomb/whatever before pushing. I thought these changes were harmless enough to just push.

    Thanks for the additional theory. I'll ponder it tomorrow. Feel free to beat me to the solution in the mean time.

  6. Steve Borho reporter

    I've got no problem with the patches or that you pushed them. The timing of it just confused me for a few moments.

    I think I'll add code to check the return of DestroyWindow and call GetLastError() and see if I uncover anything.

  7. Adrian Buehlmann

    Oh. I think might need:

    diff --git a/TortoiseHgOverlayServer.py b/TortoiseHgOverlayServer.py
    --- a/TortoiseHgOverlayServer.py
    +++ b/TortoiseHgOverlayServer.py
    @@ -412,7 +412,7 @@ class PipeServer:
         def SvcStop(self):
             logger.msg('PipeServer thread terminating')
             win32event.SetEvent(self.hWaitStop)
    -        requests.put('terminate')
    +        requests.put('terminate|')
    
         def SvcDoRun(self):
             # We create our named pipe.
    

    (Now really logging off...)

  8. Steve Borho reporter

    I made a change with the above terminate| fix and my debugging messages, built an installer, then made a doc change and built a second installer.

    Now I can run the two of them back and forth to test things.

    I get this in the log file now:

    [02/23/11 20:20:43] Shell notified
    [02/23/11 20:27:14] PipeServer received terminate from pipe
    [02/23/11 20:27:14] Updater thread terminating
    [02/23/11 20:27:14] WARNING: something went wrong in requests.put
    [02/23/11 20:27:14] Traceback (most recent call last):
      File "TortoiseHgOverlayServer.py", line 475, in SvcDoRun
    error: (1400, 'PostMessage', 'Invalid window handle.')
    
  9. Steve Borho reporter

    The PostMessage error only happened the one time, and it may have occurred when I was running the overlay server as source. I can no longer tell.

    The pair of nearly identical installers still leave the overlay server in a stuck state. And now I'm getting permission errors again on every other installer exit. Ugh.

    My last two logfiles:

    [02/23/11 20:34:57] TortoiseHg Overlay Icon Server, Version 1.9.3+137-20ed39e10b
    [02/23/11 20:34:58] Logging to file started
    [02/23/11 20:35:23] Updated c:\thg-winbuild
    [02/23/11 20:35:25] Shell notified
    [02/23/11 20:35:49] PipeServer received terminate from pipe
    [02/23/11 20:35:49] Updater thread terminating
    [02/23/11 20:35:50] Stopping pipe server...
    [02/23/11 20:35:50] PipeServer thread terminating
    [02/23/11 20:35:50] PipeServer thread terminating
    [02/23/11 20:35:50] Updater thread terminating
    [02/23/11 20:35:50] DestroyWindow returned None
    [02/23/11 20:35:50] GetLastError returned 0
    [02/23/11 20:35:50] Goodbye
    
    [02/23/11 20:34:06] TortoiseHg Overlay Icon Server, Version 1.9.3+136-7a782005fe
    [02/23/11 20:34:06] Logging to file started
    [02/23/11 20:34:16] Updated c:\thg-winbuild
    [02/23/11 20:34:18] Shell notified
    [02/23/11 20:34:31] PipeServer received terminate from pipe
    [02/23/11 20:34:31] Updater thread terminating
    [02/23/11 20:34:32] PipeServer thread terminating
    [02/23/11 20:34:32] Stopping pipe server...
    [02/23/11 20:34:32] pipethread is not alive
    [02/23/11 20:34:32] DestroyWindow returned None
    [02/23/11 20:34:32] GetLastError returned 0
    [02/23/11 20:34:32] Goodbye
    

    I've run out of time myself for today

  10. Adrian Buehlmann

    I think we are getting closer now.

    What might be interesting is, the fact that during installation, I think Explorer is terminated, then files exchanged, then the new overlay server started *while Explorer is not running*.

    I'm wondering how the overlay server can create a window if explorer isn't running.

  11. Adrian Buehlmann

    Perhaps we should simply trying to sidestep the issue by not starting the overlay server during installation.

    Of course this would require that we make the shell extension more pungent in starting the overlay server. Today, the shell ext only starts the overlay server on "Update Icons".

  12. Adrian Buehlmann

    Which might lead to new problems when the installer tries to shutdown the overlay server. Sigh...

    (<rant>Why oh why can't Windows exchange files while they are open. I want Windows with the Linux file handling... If I ever run into Steve Ballmer, I need to have a serious talk with him.)

  13. Steve Borho reporter

    I had similar thoughts of decoupling the overlay server launch from the installer.

    Perhaps the server could be started when the explorer first loads the extension if it doesn't find the named pipe?

  14. Adrian Buehlmann

    Hold on. It think I found something interesting.

    We've looked at the running TortoiseHgOverlayServer.exe here using the Sysinternals Process Explorer.

    If TortoiseHgOverlayServer.exe was started by the installer, it is holding two references to the named pipe! If it is started manually, there is only one.

    MainWindow.OnRestart looks fishy. I need to have a closer look, but it might be that we end having excess threads.

    It looks like MainWindow.OnRestart is called when explorer starts. I need to add some more logging statements...

    I'd bet I'm close to solving this.

  15. Adrian Buehlmann

    Yep. From reading the code I think we need:

    diff --git a/TortoiseHgOverlayServer.py b/TortoiseHgOverlayServer.py
    --- a/TortoiseHgOverlayServer.py
    +++ b/TortoiseHgOverlayServer.py
    @@ -109,6 +109,7 @@ def SetIcon(hwnd, name, add=False):
    
     class MainWindow:
         def __init__(self):
    +        self.pipethread = None
             msg_TaskbarRestart = RegisterWindowMessage("TaskbarCreated");
             message_map = {
                     msg_TaskbarRestart: self.OnRestart,
    @@ -207,6 +208,9 @@ class MainWindow:
                 return True
    
         def start_pipe_server(self):
    +        if self.pipethread is not None:
    +            return
    +
             def servepipe():
                 self.svc = PipeServer(self.hwnd)
                 self.svc.SvcDoRun()
    

    I'll test this later this evening.

  16. Adrian Buehlmann

    Ok. Using 423a0f266bad I can repro the problem running from source by doing

    • start the overlay server with "python TortoiseHgOverlayServer.py"
    • restarting Explorer

    The python process now has two handles open on the named pipe

    • Exit the overlay server using "Exit" from the taskbar cmenu

    Now, "python TortoiseHgOverlayServer.py" is still running (wrong)

    $ python TortoiseHgOverlayServer.py
    L[02/24/11 18:15:37] TortoiseHg Overlay Icon Server, Version 10594.diff
    L[02/24/11 18:15:37] Logging to file started
    SetIcon(hg.ico)
    L[02/24/11 18:15:37] PipeServer.SvcDoRun
    L[02/24/11 18:16:56] MainWindow.OnRestart
    SetIcon(hg.ico)
    L[02/24/11 18:16:57] PipeServer.SvcDoRun
    L[02/24/11 18:19:07] MainWindow.exit_application
    L[02/24/11 18:19:07] MainWindow.stop_pipe_server
    L[02/24/11 18:19:07] PipeServer.SvcStop
    testing pipe [try 1] ...
    L[02/24/11 18:19:07] Updater thread terminating
    L[02/24/11 18:19:07] Traceback (most recent call last):
      File "TortoiseHgOverlayServer.py", line 198, in stop_pipe_server
        self.pipethread.terminate()
      File "C:\Users\adi\hgrepos\thg-qt\tortoisehg\util\thread2.py", line 52, in terminate
        self.raise_exc(SystemExit)
      File "C:\Users\adi\hgrepos\thg-qt\tortoisehg\util\thread2.py", line 47, in raise_exc
        _async_raise(self._get_my_tid(), exctype)
      File "C:\Users\adi\hgrepos\thg-qt\tortoisehg\util\thread2.py", line 31, in _get_my_tid
        raise threading.ThreadError("the thread is not active")
    error: the thread is not active
    
    L[02/24/11 18:19:07] MainWindow.OnDestroy
    L[02/24/11 18:19:07] Goodbye
    
  17. Adrian Buehlmann

    I've tested this by building two msi from the same changeset and installing one after the other on Windows 7 SP1 x64. Overlay server is shut down as expected.

    C:\Users\adi\AppData\Roaming\TortoiseHg\OverlayServerLog.txt contains

    [02/24/11 19:02:06] TortoiseHg Overlay Icon Server, Version 1.9.3+147-8fe6e124b319
    [02/24/11 19:02:07] Logging to file started
    [02/24/11 19:02:07] PipeServer.SvcDoRun
    [02/24/11 19:02:08] MainWindow.OnRestart
    [02/24/11 19:03:09] Updated c:\users\adi\hgrepos\thg-qt
    [02/24/11 19:03:11] Shell notified
    

    Yay!

  18. Adrian Buehlmann

    Contents of

    C:\Users\adi\AppData\Roaming\TortoiseHg\OverlayServerLog.txt.old was

    [02/24/11 18:59:57] TortoiseHg Overlay Icon Server, Version 1.9.3+147-8fe6e124b319
    [02/24/11 18:59:57] Logging to file started
    [02/24/11 18:59:57] PipeServer.SvcDoRun
    [02/24/11 18:59:59] MainWindow.OnRestart
    [02/24/11 19:00:10] Removing C:\Users\adi\hgrepos\tests
    [02/24/11 19:00:11] Updated c:\users\adi\hgrepos\tests\b
    [02/24/11 19:00:11] Updated c:\users\adi\hgrepos\tests\b2
    [02/24/11 19:00:11] Updated c:\users\adi\hgrepos\tests\hg-crew-test
    [02/24/11 19:00:13] Shell notified
    [02/24/11 19:01:18] PipeServer received terminate from pipe
    [02/24/11 19:01:18] Updater thread terminating
    [02/24/11 19:01:19] PipeServer.SvcStop
    [02/24/11 19:01:19] MainWindow.exit_application
    [02/24/11 19:01:19] MainWindow.stop_pipe_server
    [02/24/11 19:01:19] pipethread is not alive
    [02/24/11 19:01:19] MainWindow.OnDestroy
    [02/24/11 19:01:20] Goodbye
    
  19. Log in to comment