[bug #64806] "invalid output sync mutex" on windows

[Gergely Pinter]

Follow-up Comment #27, bug#64806 (group make):

I went on with analysis of the situation as follows.  When processes are
apparently hung, they are waiting for a handle whose numeric value equals the
handle of the mutex created by the root process (0x128 in the example below). 
At this point Process Explorer indicates that 0x128 in a grandchild process
(18728) that is waiting is not a mutex, but "\Device\ConDrv" (see attached
screenshot).  Surprisingly, if one hits ENTER in the terminal window of "hung"
processes, their execution resumes.  At this point I suspected that when we
think that we are waiting for the mutex in osync_acquire(), in reality we are
waiting for the standard input (which would explain the phenomenon that
hitting ENTER resumes execution).  Added instrumentation that logs in separate
files calls to CreateMutex(), WaitForSingleObject() and CloseHandle() in
w32os.c and CloseHandle() and CreateProcess() in sub_proc.c.  Let the root
process be of PID 2728, its child 7116, grandchild 18728 as shown in the
attached screenshot.  According to the log, the following happens (log entries
are in the form "[PID] FILE:FUNCTION: logged API call", only relevant lines
and only from processes 2728, 7116 and 18728 kept, lines were originally
timestamped and ordered, timestamps are hidden for readability):

[2728]  w32os.c:osync_setup: CreateMutex(): 0x128         <<< 2728 creates
mutex with handle 0x128
[...]
[2728]  sub_proc.c:process_begin: CreateProcess: 7116     <<< 2728 creates
process 7116 that inherits
                                                          <<< handle 0x128
referring to the mutex
[...]
[7116]  w32os.c:osync_acquire: WaitForSingleObject(0x128) <<< 7116 uses the
mutex via handle 0x128
[...]
[7116]  w32os.c:osync_acquire: WaitForSingleObject(0x128) <<< 7116 still uses
the mutex via handle 0x128
[...]
[7116]  w32os.c:osync_clear: CloseHandle(0x128)           <<< 7116 closes
handle of the mutex
[...]
[7116]  sub_proc.c:process_begin: CreateProcess: 18728    <<< 7116 creates
process 18728 that may inherit a handle
                                                          <<< 0x128 but it is
not a mutex any more but probably
                                                          <<< some terminal
stream, most probably obtained when
                                                          <<< redirecting
stdin/out etc.
[...]
[18728] w32os.c:osync_acquire: WaitForSingleObject(0x128) <<< 18728 tries to
wait for the "mutex" but in reality
                                                          <<< it is waiting
for something else resulting in hang

As indicated in the comments above, if I am not mistaken, the grandchild
process 18728 did not inherit the mutex in handle 0x128 as intended, but 0x128
refers to something else, this seems to be the reason for the hang.

Commenting out the CloseHandle() call from in osync_clear() eliminates the
hang: the entire compilation goes fine, even output synchronization is OK. 
(Removing CloseHandle() is clearly undesired practice, but since Windows
should close any open handles when a process terminates, this temporary
workaround is probably not a long-term resource leak).

To put together: closing the mutex handle before creating a child process that
is expected to use that mutex by inheriting the handle, seems to be the root
cause of the phenomenon.  Maybe this is related to inclusion of dependency
files that had to be created by make.


(file #55583)

    _______________________________________________________

Additional Item Attachment:

File name: mingw32-make-procexp.png       Size:25 KB
   
<https://file.savannah.gnu.org/file/mingw32-make-procexp.png?file_id=55583>


    AGPL NOTICE

These attachments are served by Savane. You can download the corresponding
source code of Savane at
https://git.savannah.nongnu.org/cgit/administration/savane.git/snapshot/savane-d1e0f7a1b19199bb94f733b79bf92733e4fe5029.tar.gz


    _______________________________________________________

Reply to this item at:

  <https://savannah.gnu.org/bugs/?64806>

_______________________________________________
Message sent via Savannah
https://savannah.gnu.org/