delorie.com/archives/browse.cgi   search  
Mail Archives: cygwin-developers/2002/09/08/13:58:12

Mailing-List: contact cygwin-developers-help AT cygwin DOT com; run by ezmlm
List-Subscribe: <mailto:cygwin-developers-subscribe AT cygwin DOT com>
List-Archive: <http://sources.redhat.com/ml/cygwin-developers/>
List-Post: <mailto:cygwin-developers AT cygwin DOT com>
List-Help: <mailto:cygwin-developers-help AT cygwin DOT com>, <http://sources.redhat.com/ml/#faqs>
Sender: cygwin-developers-owner AT cygwin DOT com
Delivered-To: mailing list cygwin-developers AT cygwin DOT com
Date: Sun, 8 Sep 2002 21:55:42 +0400
From: egor duda <deo AT logos-m DOT ru>
Reply-To: egor duda <cygwin-developers AT cygwin DOT com>
Organization: deo
X-Priority: 3 (Normal)
Message-ID: <1615258000.20020908215542@logos-m.ru>
To: Christopher Faylor <cygwin-developers AT cygwin DOT com>
Subject: Re: hang in sig_wait waiting for debug lock
In-Reply-To: <20020908170046.GB7279@redhat.com>
References: <7710998905 DOT 20020828173811 AT logos-m DOT ru>
<20020905153320 DOT GC16827 AT redhat DOT com> <591948241 DOT 20020906185459 AT logos-m DOT ru>
<20020906151713 DOT GC21699 AT redhat DOT com> <1176882135 DOT 20020906201713 AT logos-m DOT ru>
<20020906210506 DOT GB26002 AT redhat DOT com> <195826558 DOT 20020908204151 AT logos-m DOT ru>
<20020908170046 DOT GB7279 AT redhat DOT com>
MIME-Version: 1.0

Hi!

Sunday, 08 September, 2002 Christopher Faylor cgf AT redhat DOT com wrote:

CF> If you don't want to understand what's going on then that is perfectly
CF> fine.  However, please don't just assume that if turning on an ifdef
CF> causes a problem to apparently go away that you've done anything more
CF> than add an additional delay to cygwin or moved something to a different
CF> memory location or something.

I'm doing my best to understand how things work. And i concluded that
for handle protection to work right it's essential to update the list
whenever we call DuplicateHandle() and replace some handle with its
duplicate. Maybe i'm wrong here, please correct me if so.
Next, i've come over setclexec and then realized that it was disabled.
So, i'm slightly puzzled. Probably i misunderstood how handle
protection works. Is protected handles list directly inherited from
parent process, or recreated from scratch when cygwin initialization
code processes a list of fhandlers passed from parent?

Here's an strace which demonstrates the problem.

  693 4839233 [main] expect 238 tty::make_pipes: tty1 from_slave 0x264, to_slave 0x210
  167 4839400 [main] expect 238 tty::get_event: created event cygtty1.input.avail
  118 4839518 [main] expect 238 add_handle: protecting handle 'output_mutex', inherited flag 1
   79 4839597 [main] expect 238 add_handle: protecting handle 'input_mutex', inherited flag 1
   75 4839672 [main] expect 238 tty::common_init: tty1 opened
   89 4839761 [main] expect 238 tty::create_inuse: cygtty1.master_alive = 0x214
   78 4839839 [main] expect 238 fhandler_base::set_flags: flags 0x10002, supplied_bin 0x0
   71 4839910 [main] expect 238 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
   71 4839981 [main] expect 238 fhandler_base::set_flags: filemode set to binary
   70 4840051 [main] expect 238 fhandler_pty_master::open: opened pty master tty1<0x616278AC>
   71 4840122 [main] expect 238 _open: 8 = open (/dev/ptmx, 0x2)
  827 4840949 [main] expect 238 fhandler_pty_master::set_close_on_exec: from_slave 0x274, to_slave 0x188
   76 4841025 [main] expect 238 _fcntl: 0 = fcntl (8, 2, 0x1)
  153 4841178 [main] expect 238 dtable::build_fhandler: fd 9, fh 0x61627A5C
   85 4841263 [main] expect 238 dtable::build_fhandler: fd 10, fh 0x61627BBC
   74 4841337 [main] expect 238 fhandler_base::set_flags: flags 0x10000, supplied_bin 0x0
   71 4841408 [main] expect 238 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
   69 4841477 [main] expect 238 fhandler_base::set_flags: filemode set to binary
   69 4841546 [main] expect 238 fhandler_base::init: created new fhandler_base for handle 0xA4, bin 1
   70 4841616 [main] expect 238 fhandler_base::set_flags: flags 0x10001, supplied_bin 0x0
   69 4841685 [main] expect 238 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
   70 4841755 [main] expect 238 fhandler_base::set_flags: filemode set to binary
   70 4841825 [main] expect 238 fhandler_base::init: created new fhandler_base for handle 0x8, bin 1
   75 4841900 [main] expect 238 make_pipe: 0 = make_pipe ([9, 10], 16384, 0x10000)
  129 4842029 [main] expect 238 dtable::build_fhandler: fd 11, fh 0x61627604
   84 4842113 [main] expect 238 dtable::build_fhandler: fd 12, fh 0x61627AE4
   73 4842186 [main] expect 238 fhandler_base::set_flags: flags 0x10000, supplied_bin 0x0
   70 4842256 [main] expect 238 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
   70 4842326 [main] expect 238 fhandler_base::set_flags: filemode set to binary
   69 4842395 [main] expect 238 fhandler_base::init: created new fhandler_base for handle 0xA0, bin 1
   85 4842480 [main] expect 238 fhandler_base::set_flags: flags 0x10001, supplied_bin 0x0
   71 4842551 [main] expect 238 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
   69 4842620 [main] expect 238 fhandler_base::set_flags: filemode set to binary
   71 4842691 [main] expect 238 fhandler_base::init: created new fhandler_base for handle 0x2AC, bin 1
   74 4842765 [main] expect 238 make_pipe: 0 = make_pipe ([11, 12], 16384, 0x10000)
  128 4842893 [main] expect 238 dtable::build_fhandler: fd 13, fh 0x61625E6C
   84 4842977 [main] expect 238 dtable::build_fhandler: fd 14, fh 0x616283CC
   73 4843050 [main] expect 238 fhandler_base::set_flags: flags 0x10000, supplied_bin 0x0
   70 4843120 [main] expect 238 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
   70 4843190 [main] expect 238 fhandler_base::set_flags: filemode set to binary
   69 4843259 [main] expect 238 fhandler_base::init: created new fhandler_base for handle 0x23C, bin 1
   70 4843329 [main] expect 238 fhandler_base::set_flags: flags 0x10001, supplied_bin 0x0
   70 4843399 [main] expect 238 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
   69 4843468 [main] expect 238 fhandler_base::set_flags: filemode set to binary
   69 4843537 [main] expect 238 fhandler_base::init: created new fhandler_base for handle 0x2A4, bin 1
   75 4843612 [main] expect 238 make_pipe: 0 = make_pipe ([13, 14], 16384, 0x10000)
   74 4843686 [main] expect 238 fork: entering
  201 4843887 [main] expect 238 add_handle: protecting handle 'subproc_ready', inherited flag 1
   86 4843973 [main] expect 238 add_handle: protecting handle 'forker_finished', inherited flag 1
   86 4844059 [main] expect 238 stack_base: bottom 0x2480000, top 0x480000, stack 0x2478FA8, size 28760, reserve 33554432
   87 4844146 [main] expect 238 fork_parent: CreateProcess (e:\unix\usr\local\bin\expect.exe, e:\unix\usr\local\bin\expect.exe, 0, 0, 1, 20, 0, 0, 0x2479438, 0x2479488)
  141 4844287 [main] expect 238 add_handle: protecting handle 'passed_cygheap_h', inherited flag 1
 1194 4845481 [main] expect 238 delete_handle: nuking handle 'passed_cygheap_h'
  245 4845726 [main] expect 238 add_handle: protecting handle 'pinfo_shared_handle', inherited flag 0
  101 4845827 [main] expect 238 add_handle: protecting handle 'pi.hThread', inherited flag 0
   82 4845909 [main] expect 238 add_handle: protecting handle 'childhProc', inherited flag 0
   79 4845988 [main] expect 238 proc_subproc: args: 1, 38245416
   81 4846069 [main] expect 238 add_handle: protecting handle 'pid_handle', inherited flag 0
  160 4846229 [main] expect 238 proc_subproc: added pid 150 to wait list, slot 0, winpid 0x96, handle 0x204
   82 4846311 [main] expect 238 proc_subproc: returning 1
   77 4846388 [main] expect 238 add_handle: protecting handle 'fork_stupidity', inherited flag 0
   77 4846465 [main] expect 238 sync_with_child: waiting for child.  reason: waiting for longjmp, hang_child 1
   91 4846556 [proc] expect 238 wait_subproc: looping
**********************************************
Program name: e:\unix\usr\local\bin\expect.exe (150)
App version:  1001.3, api: 0.21
DLL version:  1003.13, api: 0.62
DLL build:    2002-09-08 20:30
OS version:   Windows NT-4.0
Date/Time:    2002-09-08 21:35:57
**********************************************
   98    3501 [unknown (0x101)] expect 150 open_shared: name shared, shared 0xA000000 (wanted 0xA000000), h 0x54
 1773    5274 [unknown (0x101)] expect 150 heap_init: heap base 0xA010000, heap top 0xA0A7000
  192    5466 [unknown (0x101)] expect 150 open_shared: name duda, shared 0x2AC0000 (wanted 0x0), h 0x78
   82    5548 [unknown (0x101)] expect 150 memory_init: opening mount table for 'duda' at 0xA010000
   94    5642 [unknown (0x101)] expect 150 memory_init: mount table version 31DF at 0x2AC0000
  195    5837 [main] expect 150 add_handle: protecting handle 'hMainProc', inherited flag 0
   81    5918 [main] expect 150 add_handle: protecting handle 'hMainThread', inherited flag 0
  150    6068 [main] expect 150 add_handle: protecting handle 'title_mutex', inherited flag 0
   97    6165 [main] expect 150 events_init: windows_system_directory 'D:\WINNT40\System32\', windows_system_directory_length 20
   72    6237 [main] expect 150 events_init: cygwin_hmodule 0x61000000
  254    6491 [main] expect 150 fork_child: child is running.  pid 150, ppid 238, stack here 0x24794B0
   79    6570 [main] expect 150 sync_with_parent: signalling parent: after longjmp.
10830 4857386 [main] expect 238 sync_with_child: child signalled me
   92 4857478 [main] expect 238 fork_parent: child is alive (but stopped)
  308 4857786 [main] expect 238 fork_copy: child handle 0x204, low 0x46E000, high 0x472128, res 1
  133 4857919 [main] expect 238 fork_copy: child handle 0x204, low 0x473000, high 0x474C30, res 1
 4040 4861959 [main] expect 238 fork_copy: child handle 0x204, low 0xA010000, high 0xA0A7000, res 1
  369 4862328 [main] expect 238 fork_copy: child handle 0x204, low 0x24794B8, high 0x2480000, res 1
  879 4863207 [main] expect 238 fork_copy: child handle 0x204, low 0x610C7000, high 0x610CA710, res 1
 1520 4864727 [main] expect 238 fork_copy: child handle 0x204, low 0x610E7000, high 0x6111F210, res 1
  191 4864918 [main] expect 238 fork_copy: done
4858447 4865017 [main] expect 150 sync_with_parent: awake
   79 4865096 [main] expect 150 sync_with_parent: no problems
   73 4865169 [main] expect 150 fork_child: hParent 0x1F0, child 1 first_dll 0x0, load_dlls 0
  171 4865340 [main] expect 150 set_file_api_mode: File APIs set to OEM
   88 4865428 [main] expect 150 dtable::fixup_after_fork: fd 0 (/dev/tty0)
   88 4865516 [main] expect 150 fhandler_base::fixup_after_fork: inheriting '/dev/tty0' from parent
   73 4865589 [main] expect 150 fhandler_base::fork_fixup: handle 0x44 already opened
   71 4865660 [main] expect 150 fhandler_base::fork_fixup: handle 0x1C0 already opened
   88 4865748 [main] expect 150 fhandler_base::fork_fixup: handle 0x180 already opened
   71 4865819 [main] expect 150 fhandler_base::fork_fixup: handle 0x15C already opened
   66 4865885 [main] expect 150 fhandler_base::fork_fixup: handle 0x10C already opened
   67 4865952 [main] expect 150 fhandler_base::fork_fixup: handle 0x100 already opened
   67 4866019 [main] expect 150 fhandler_base::fork_fixup: handle 0xBC already opened
   66 4866085 [main] expect 150 fhandler_base::fork_fixup: handle 0x9C already opened
   67 4866152 [main] expect 150 fhandler_base::fork_fixup: handle 0x28 already opened
   69 4866221 [main] expect 150 dtable::fixup_after_fork: fd 1 (/dev/tty0)
   66 4866287 [main] expect 150 fhandler_base::fixup_after_fork: inheriting '/dev/tty0' from parent
   68 4866355 [main] expect 150 fhandler_base::fork_fixup: handle 0x140 already opened
   66 4866421 [main] expect 150 fhandler_base::fork_fixup: handle 0x48 already opened
   67 4866488 [main] expect 150 fhandler_base::fork_fixup: handle 0xA8 already opened
   65 4866553 [main] expect 150 fhandler_base::fork_fixup: handle 0xC already opened
 1708 4866626 [main] expect 238 resume_child: signalled child
   73 4866699 [main] expect 238 sync_with_child: waiting for child.  reason: child loading dlls, hang_child 0
  440 4866993 [main] expect 150 fhandler_base::fork_fixup: handle 0x16C already opened
   80 4867073 [main] expect 150 fhandler_base::fork_fixup: handle 0x11C already opened
   73 4867146 [main] expect 150 fhandler_base::fork_fixup: handle 0x13C already opened
   68 4867214 [main] expect 150 fhandler_base::fork_fixup: handle 0x1BC already opened
   70 4867284 [main] expect 150 fhandler_base::fork_fixup: handle 0x8C already opened
   69 4867353 [main] expect 150 dtable::fixup_after_fork: fd 2 (/dev/tty0)
   69 4867422 [main] expect 150 fhandler_base::fixup_after_fork: inheriting '/dev/tty0' from parent
   68 4867490 [main] expect 150 fhandler_base::fork_fixup: handle 0x120 already opened
   70 4867560 [main] expect 150 fhandler_base::fork_fixup: handle 0xC4 already opened
   68 4867628 [main] expect 150 fhandler_base::fork_fixup: handle 0x108 already opened
   91 4867719 [main] expect 150 fhandler_base::fork_fixup: handle 0x150 already opened
   71 4867790 [main] expect 150 fhandler_base::fork_fixup: handle 0x158 already opened
   70 4867860 [main] expect 150 fhandler_base::fork_fixup: handle 0x18C already opened
   69 4867929 [main] expect 150 fhandler_base::fork_fixup: handle 0x1E0 already opened
   69 4867998 [main] expect 150 fhandler_base::fork_fixup: handle 0x104 already opened
   68 4868066 [main] expect 150 fhandler_base::fork_fixup: handle 0x154 already opened
   79 4868145 [main] expect 150 dtable::fixup_after_fork: fd 5 (/dev/tty0)
   73 4868218 [main] expect 150 fhandler_base::fixup_after_fork: inheriting '/dev/tty0' from parent
   70 4868288 [main] expect 150 fhandler_base::fork_fixup: handle 0x178 already opened
   69 4868357 [main] expect 150 fhandler_base::fork_fixup: handle 0x174 already opened
   68 4868425 [main] expect 150 fhandler_base::fork_fixup: handle 0xB8 already opened
   68 4868493 [main] expect 150 fhandler_base::fork_fixup: handle 0x14C already opened
   69 4868562 [main] expect 150 fhandler_base::fork_fixup: handle 0x164 already opened
   68 4868630 [main] expect 150 fhandler_base::fork_fixup: handle 0x110 already opened
   68 4868698 [main] expect 150 fhandler_base::fork_fixup: handle 0x1DC already opened
   68 4868766 [main] expect 150 fhandler_base::fork_fixup: handle 0xB4 already opened
   68 4868834 [main] expect 150 fhandler_base::fork_fixup: handle 0x170 already opened
   69 4868903 [main] expect 150 dtable::fixup_after_fork: fd 6 (/cygdrive/j/build/i586-pc-cygwin/gcc/i686-pc-cygwin/libstdc++-v3/testsuite/libstdc++-v3.sum)
   79 4868982 [main] expect 150 fhandler_base::fixup_after_fork: inheriting '/cygdrive/j/build/i586-pc-cygwin/gcc/i686-pc-cygwin/libstdc++-v3/testsuite/libstdc++-v3.sum' from parent
   89 4869071 [main] expect 150 dtable::fixup_after_fork: fd 7 (/cygdrive/j/build/i586-pc-cygwin/gcc/i686-pc-cygwin/libstdc++-v3/testsuite/libstdc++-v3.log)
   74 4869145 [main] expect 150 fhandler_base::fixup_after_fork: inheriting '/cygdrive/j/build/i586-pc-cygwin/gcc/i686-pc-cygwin/libstdc++-v3/testsuite/libstdc++-v3.log' from parent
   81 4869226 [main] expect 150 dtable::fixup_after_fork: fd 8 (/dev/ptym)
   70 4869296 [main] expect 150 fhandler_base::fixup_after_fork: inheriting '/dev/ptym' from parent
  111 4869407 [main] expect 150 add_handle: protecting handle 'hParent', inherited flag 1
  101 4869508 [main] expect 150 add_handle: void sigproc_init():563 - multiple attempts to add handle wait_sig_inited<0x210>
   99 4869607 [main] expect 150 add_handle:  previously allocated by int tty::make_pipes(fhandler_pty_master*):370(to_pty<0x210>) winpid 137
   94 4869701 [main] expect 150 add_handle: protecting handle 'signal_arrived', inherited flag 0
  350 4870051 [main] expect 150 sigproc_init: process/signal handling enabled(1801)
   73 4870124 [main] expect 150 fixup_mmaps_after_fork: recreate_mmaps_after_fork, mmapped_areas 0x0
   71 4870195 [main] expect 150 sync_with_parent: signalling parent: performed fork fixup.
 3572 4870271 [main] expect 238 sync_with_child: child signalled me
   79 4870350 [main] expect 238 delete_handle: nuking handle 'subproc_ready'
   75 4870425 [main] expect 238 delete_handle: nuking handle 'pi.hThread'
   73 4870498 [main] expect 238 delete_handle: nuking handle 'forker_finished'
   76 4870574 [main] expect 238 fork: 150 = fork()

>>CF> Possibly.  Are you seeing system_printf output in your failing case?
>>
>>Yes, but it looks that it not full. Actually, pipe hasn't to be filled
>>up. After WriteFile() we call FlushFileBuffers (). Documentation on
>>FlushFileBuffers states that if handle is a pipe then the operation
>>blocks until pipe peer reads _all_ data from pipe. Commenting
>>FlushFileBuffers did helped in my case -- system_printf()s are not
>>blocking process now.
>>
>>Yet i suppose the right way is to always unlock debug muto as fast as
>>possible, i.e., before calling debug_printf() and stuff. As far as i
>>understand, muto is protecting handle list, so we must hold it while
>>and only while we're messing with it. That should be safe.

CF> Possibly.  Personally, I'm much more bothered by the fact that there
CF> are system_printfs at all.  AFAICT, you only mention this in passing
CF> but a system_printf is an indication of a problem in cygwin.

Agreed. But if we really want process to block whenever it encounters
system_printf, we can possibly do it in less sophisticated (and
confusing) way :) 

Egor.            mailto:deo AT logos-m DOT ru ICQ 5165414 FidoNet 2:5020/496.19

- Raw text -


  webmaster     delorie software   privacy  
  Copyright © 2019   by DJ Delorie     Updated Jul 2019