X-Recipient: archive-cygwin AT delorie DOT com X-SWARE-Spam-Status: No, hits=-1.5 required=5.0 tests=AWL,BAYES_00,DKIM_SIGNED,DKIM_VALID,DKIM_VALID_AU,FREEMAIL_FROM,RCVD_IN_DNSWL_NONE,T_TO_NO_BRKTS_FREEMAIL X-Spam-Check-By: sourceware.org MIME-Version: 1.0 In-Reply-To: <20100629083055.GZ8163@calimero.vinschen.de> References: <20100628183440 DOT GA18422 AT ednor DOT casa DOT cgf DOT cx> <20100629083055 DOT GZ8163 AT calimero DOT vinschen DOT de> Date: Tue, 29 Jun 2010 10:48:49 +0100 Message-ID: Subject: Re: 1.7.6 snapshot: intermittent "CreateProcessW failed" From: Andy Koppe To: cygwin AT cygwin DOT com Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: quoted-printable X-IsSubscribed: yes Mailing-List: contact cygwin-help AT cygwin DOT com; run by ezmlm Precedence: bulk List-Id: List-Unsubscribe: List-Subscribe: List-Archive: List-Post: List-Help: , Sender: cygwin-owner AT cygwin DOT com Mail-Followup-To: cygwin AT cygwin DOT com Delivered-To: mailing list cygwin AT cygwin DOT com On 29 June 2010 09:30, Corinna Vinschen wrote: > On Jun 29 09:16, Andy Koppe wrote: >> On 28 June 2010 19:34, Christopher Faylor wrote: >> > On Mon, Jun 28, 2010 at 05:36:04PM +0100, Andy Koppe wrote: >> >>When running a couple of lengthy make-based builds in parallel, I >> >>eventually get error messages such as this: >> >> >> >> =C2=A0 =C2=A0 =C2=A03 [main] sh 4368 fork: child -1 - CreateProcessW = failed, errno 2 >> >>/bin/sh: fork: No such file or directory >> >> >> >> =C2=A0 =C2=A0 =C2=A05 [main] make 5736 fork: child -1 - CreateProcess= W failed, errno 2 >> >>make[2]: vfork: No such file or directory >> >> >> >>The errors aren't reproducible, i.e. when rerunning, one of the build >> >>fails elsewhere with the same sort of error. Hence I'm unable to >> >>provide a small testcase. >> >> >> >>It doesn't fail if I run just one build at a time, and it fails more >> >>quickly if I run more than two. I guess this suggests a >> >>synchronisation issue. >> >> >> >>This is on a 32-bit Windows XP. The issue didn't occur on 1.7.5 and >> >>before. I went back through previous snapshots to try to narrow to >> >>down the problem a little bit: 20100507 is fine, 20100518 is not. >> > >> > Hmm. =C2=A0That means that it is related to the change to use wide cha= racters >> > for the current program name but I've reviewed the patch again and don= 't >> > see anything obvious. >> > >> > Could you try this on the latest snapshot when it shows up. =C2=A0I've= added a >> > tad more debugging to the error message. >> >> =C2=A0 =C2=A0 =C2=A0 4 [main] sh 396 fork: child -1 - CreatProcessW fail= ed for >> '\??\C:\bin\sh.exe', errno 2 > > Looks like the path is missing a directory. =C2=A0I assume you didn't > install Cygwin to C:\ but to C:\cygwin, right? =C2=A0Or does the path > make sense when ignoring the NT prefix "\??\"? The path is correct. C:/bin on /usr/bin type ntfs (binary,auto) C:/lib on /usr/lib type ntfs (binary,auto) C: on / type ntfs (binary,auto) Unfortunately the top-level make just exits early before really doing anything if I run it through strace (see below). It starts doing actual work if I add '-f' to the strace arguments, but then of course strace no longer captures events in sub-makes, which is where the problem occurs. Andy tail -100 make.strace 1444 32925179 [sig] make 6096 proc_subproc: finished processing terminated/stopped child 44 32925223 [sig] make 6096 proc_subproc: returning 1 36 32925259 [sig] make 6096 wait_sig: signalling pack.wakeup 0x68C 40 32925299 [main] make 6096 reset_signal_arrived: reset signal_arrived 29 32925328 [main] make 6096 reset_signal_arrived: stackptr[-1] 0x40CD5F 26 32925354 [main] make 6096 set_process_mask_delta: oldmask 0x4000, newmask 0x84000, deltamask 0x80000 27 32925381 [main] make 6096 set_signal_mask: oldmask 0x84000, newmask 0x4000, mask_bits 0x80000 28 32925409 [main] make 6096 sig_send: sendsig 0x748, pid 6096, signal -39, its_me 1 30 32925439 [main] make 6096 sig_send: wakeup 0x68C 31 32925470 [main] make 6096 sig_send: Waiting for pack.wakeup 0x68C 832 32926302 [sig] make 6096 wait_sig: signalling pack.wakeup 0x68C 55 32926357 [main] make 6096 sig_send: returning 0x0 from sending signal= -39 32 32926389 [main] make 6096 sig_send: returning 0x0 from sending signal= -34 28 32926417 [main] make 6096 wait4: calling proc_subproc, pid -1, option= s 0 40 32926457 [main] make 6096 proc_subproc: args: 4, 2284288 26 32926483 [main] make 6096 proc_subproc: wval->pid -1, wval->options 0 27 32926510 [main] make 6096 checkstate: nprocs 1 83 32926593 [main] make 6096 stopped_or_terminated: considering pid 4264 28 32926621 [main] make 6096 remove_proc: removing procs[0], pid 4264, nprocs 1 52 32926673 [main] make 6096 checkstate: returning 1 130 32926803 [main] make 6096 proc_subproc: released waiting thread 32 32926835 [main] make 6096 proc_subproc: finished processing terminated/stopped child 26 32926861 [main] make 6096 proc_subproc: returning 1 29 32926890 [main] make 6096 wait4: 0 =3D WaitForSingleObject (...) 27 32926917 [main] make 6096 wait4: intpid -1, status 0x22C05C, w->status 15, options 0, res 4264 105 32927022 [main] make 6096 __set_errno: ssize_t writev(int, const iovec*, int):982 val 9 223 32927245 [main] make 6096 __set_errno: ssize_t writev(int, const iovec*, int):982 val 9 151 32927396 [main] make 6096 __set_errno: ssize_t writev(int, const iovec*, int):982 val 9 180 32927576 [main] make 6096 set_signal_mask: oldmask 0x4000, newmask 0x1804007, mask_bits 0x0 26 32927602 [main] make 6096 set_signal_mask: not calling sig_dispatch_pending 26 32927628 [main] make 6096 set_signal_mask: oldmask 0x1804007, newmask 0x0, mask_bits 0x1804007 28 32927656 [main] make 6096 sig_send: sendsig 0x748, pid 6096, signal -39, its_me 1 30 32927686 [main] make 6096 sig_send: wakeup 0x63C 32 32927718 [main] make 6096 sig_send: Waiting for pack.wakeup 0x63C 473 32928191 [sig] make 6096 wait_sig: signalling pack.wakeup 0x63C 44 32928235 [main] make 6096 sig_send: returning 0x0 from sending signal= -39 52 32928287 [main] make 6096 kill0: kill (6096, 15) 28 32928315 [main] make 6096 sig_send: sendsig 0x748, pid 6096, signal -34, its_me 1 28 32928343 [main] make 6096 sig_send: wakeup 0x63C 30 32928373 [main] make 6096 sig_send: Waiting for pack.wakeup 0x63C 5555 32933928 [sig] make 6096 wait_sig: signalling pack.wakeup 0x63C 75 32934003 [main] make 6096 sig_send: returning 0x0 from sending signal= -34 32 32934035 [main] make 6096 sig_send: sendsig 0x748, pid 6096, signal 15, its_me 1 30 32934065 [main] make 6096 sig_send: wakeup 0x63C 31 32934096 [main] make 6096 sig_send: Waiting for pack.wakeup 0x63C 359 32934455 [sig] make 6096 sigpacket::process: signal 15 processing 41 32934496 [sig] make 6096 _cygtls::find_tls: sig 15 30 32934526 [sig] make 6096 sigpacket::process: signal 15, about to call do_exit 93 32934619 [sig] make 6096 _cygtls::signal_exit: about to call do_exit = (F) 31 32934650 [sig] make 6096 do_exit: do_exit (15), exit_state 2 36 32934686 [sig] make 6096 void: 0x40B510 =3D signal (20, 0x1) 31 32934717 [sig] make 6096 void: 0x402940 =3D signal (1, 0x1) 32 32934749 [sig] make 6096 void: 0x402940 =3D signal (2, 0x1) 29 32934778 [sig] make 6096 void: 0x402940 =3D signal (3, 0x1) 39 32934817 [sig] make 6096 init_cygheap::manage_console_count: fhandler_tty_slave::close: console_count 2, amount -1, ctty /dev/tty0, avoid_freeing_console 0 32 32934849 [sig] make 6096 fhandler_tty_slave::close: /dev/tty0 closed, usecount 2 32 32934881 [sig] make 6096 fhandler_tty_slave::close: just returning because archetype usecount is !=3D 0 33 32934914 [sig] make 6096 init_cygheap::manage_console_count: fhandler_tty_slave::close: console_count 1, amount -1, ctty /dev/tty0, avoid_freeing_console 0 31 32934945 [sig] make 6096 fhandler_tty_slave::close: /dev/tty0 closed, usecount 1 29 32934974 [sig] make 6096 fhandler_tty_slave::close: just returning because archetype usecount is !=3D 0 36 32935010 [sig] make 6096 fhandler_base::close: closing '/dev/fd/pipe:[2]' handle 0x64C 32 32935042 [sig] make 6096 init_cygheap::close_ctty: closing cygheap->ctty 0x612399E8 31 32935073 [sig] make 6096 init_cygheap::manage_console_count: fhandler_tty_slave::close: console_count 0, amount -1, ctty /dev/tty0, avoid_freeing_console 0 29 32935102 [sig] make 6096 fhandler_tty_slave::close: /dev/tty0 closed, usecount 0 30 32935132 [sig] make 6096 fhandler_tty_slave::close: closing last open /dev/tty0 handle 32 32935164 [sig] make 6096 fhandler_tty_common::close: tty0 <0x714,0x70C> closing 36 32935200 [sig] make 6096 do_exit: 6096 =3D=3D pgrp 6096, send SIG{HUP,CONT} to stopped children 29 32935229 [sig] make 6096 kill_pgrp: pid 6096, signal -1 1140 32936369 [sig] make 6096 open_shared: name cygpid.1476, n 1476, shared 0x18C70000 (wanted 0x0), h 0x70C 73 32936442 [sig] make 6096 open_shared: name cygpid.4244, n 4244, shared 0x18F10000 (wanted 0x0), h 0x7D8 35 32936477 [sig] make 6096 pinfo::init: execed process windows pid 4244, cygwin pid 4048 43 32936520 [sig] make 6096 open_shared: name cygpid.4048, n 4048, shared 0x18F10000 (wanted 0x0), h 0x7D8 48 32936568 [sig] make 6096 open_shared: name cygpid.5872, n 5872, shared 0x18F30000 (wanted 0x0), h 0x718 46 32936614 [sig] make 6096 open_shared: name cygpid.2092, n 2092, shared 0x18F50000 (wanted 0x0), h 0x680 31 32936645 [sig] make 6096 pinfo::init: execed process windows pid 2092, cygwin pid 3120 41 32936686 [sig] make 6096 open_shared: name cygpid.3120, n 3120, shared 0x18F50000 (wanted 0x0), h 0x680 64 32936750 [sig] make 6096 open_shared: name cygpid.5964, n 5964, shared 0x18F70000 (wanted 0x0), h 0x640 54 32936804 [sig] make 6096 open_shared: name cygpid.2648, n 2648, shared 0x18F90000 (wanted 0x0), h 0x630 32 32936836 [sig] make 6096 pinfo::init: execed process windows pid 2648, cygwin pid 5964 40 32936876 [sig] make 6096 open_shared: name cygpid.5964, n 5964, shared 0x18F90000 (wanted 0x0), h 0x630 54 32936930 [sig] make 6096 open_shared: name cygpid.5332, n 5332, shared 0x18F90000 (wanted 0x0), h 0x630 32 32936962 [sig] make 6096 pinfo::init: execed process windows pid 5332, cygwin pid 4300 41 32937003 [sig] make 6096 open_shared: name cygpid.4300, n 4300, shared 0x18F90000 (wanted 0x0), h 0x630 46 32937049 [sig] make 6096 open_shared: name cygpid.2192, n 2192, shared 0x18FB0000 (wanted 0x0), h 0x644 34 32937083 [sig] make 6096 pinfo::init: execed process windows pid 2192, cygwin pid 4492 42 32937125 [sig] make 6096 open_shared: name cygpid.4492, n 4492, shared 0x18FB0000 (wanted 0x0), h 0x644 48 32937173 [sig] make 6096 open_shared: name cygpid.4388, n 4388, shared 0x18FD0000 (wanted 0x0), h 0x648 69 32937242 [sig] make 6096 __set_errno: int kill_pgrp(pid_t, siginfo_t&):340 val 3 29 32937271 [sig] make 6096 kill_pgrp: -1 =3D kill (6096, -1) 129 32937400 [sig] make 6096 sigproc_terminate: entering 30 32937430 [sig] make 6096 sig_send: my_sendsig 0x748, myself->sendsig 0x748, exit_state 12 28 32937458 [sig] make 6096 __set_errno: int sig_send(_pinfo*, siginfo_t&, _cygtls*):571 val 11 27 32937485 [sig] make 6096 sig_send: returning 0x1 from sending signal = -42 28 32937513 [sig] make 6096 proc_terminate: nprocs 0 30 32937543 [sig] make 6096 proc_terminate: leaving 30 32937573 [sig] make 6096 __to_clock_t: dwHighDateTime 0, dwLowDateTime 6406250 29 32937602 [sig] make 6096 __to_clock_t: total 00000000 00000280 27 32937629 [sig] make 6096 __to_clock_t: dwHighDateTime 0, dwLowDateTime 3593750 26 32937655 [sig] make 6096 __to_clock_t: total 00000000 00000167 461 32938116 [sig] make 6096 pinfo::exit: Calling ExitProcess n 0xF, exitcode 0xF00 Andy -- Problem reports: http://cygwin.com/problems.html FAQ: http://cygwin.com/faq/ Documentation: http://cygwin.com/docs.html Unsubscribe info: http://cygwin.com/ml/#unsubscribe-simple