Re: 1.7.6 snapshot: intermittent "CreateProcessW failed"

[Andy Koppe <andy dot koppe at gmail 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:
>> >>
>> >> Â Â Â3 [main] sh 4368 fork: child -1 - CreateProcessW failed, errno 2
>> >>/bin/sh: fork: No such file or directory
>> >>
>> >> Â Â Â5 [main] make 5736 fork: child -1 - CreateProcessW 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. ÂThat means that it is related to the change to use wide characters
>> > 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. ÂI've added a
>> > tad more debugging to the error message.
>>
>> Â Â Â 4 [main] sh 396 fork: child -1 - CreatProcessW failed for
>> '\??\C:\bin\sh.exe', errno 2
>
> Looks like the path is missing a directory. ÂI assume you didn't
> install Cygwin to C:\ but to C:\cygwin, right? ÂOr 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, options 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 = 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 = signal (20, 0x1)
   31 32934717 [sig] make 6096 void: 0x402940 = signal (1, 0x1)
   32 32934749 [sig] make 6096 void: 0x402940 = signal (2, 0x1)
   29 32934778 [sig] make 6096 void: 0x402940 = 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 != 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 != 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 == 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 = 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