Mailing-List: contact cygwin-developers-help AT cygwin DOT com; run by ezmlm List-Subscribe: List-Archive: List-Post: List-Help: , 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 Reply-To: egor duda Organization: deo X-Priority: 3 (Normal) Message-ID: <1615258000.20020908215542@logos-m.ru> To: Christopher Faylor 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 Content-Type: text/plain; charset=us-ascii Content-Transfer-Encoding: 7bit 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