bash-2.05b+cygwin-1.3.12-1: script output is reordered

[Manfred Spraul]

Configuration Information [Automatically generated, do not change]:
Machine: i686
OS: cygwin
Compiler: i686-pc-cygwin-gcc
Compilation CFLAGS:  -DPROGRAM='bash.exe' -DCONF_HOSTTYPE='i686' 
-DCONF_OSTYPE='cygwin' -DCONF_MACHTYPE='i686-pc-cygwin' 
-DCONF_VENDOR='pc' -DSHELL -DHAVE_CONFI
G_H  -I.  -I../bash-2.05b -I../bash-2.05b/include -I../bash-2.05b/lib  
-g -O2
uname output: CYGWIN_NT-5.0 AB 1.3.12(0.54/3/2) 2002-07-03 16:42 i686 
unknown
Machine Type: i686-pc-cygwin

Bash Version: 2.05b
Patch Level: 0
Release Status: release

Description:
   bash output from a long script appears out of order in the output 
file. Basically, the script does
<<<
    fnc() {
           echo "X"
           cat ext-2.txt
           echo "Y"
   }
   fnc() > file.txt
<<<
   and the output is
<<<
       X
       Y
       <content of file ext-2.txt>
<<<

   I've straced bash, and it seems that the parent doesn't wait for the 
subprocess after fork():
<<<

<<< shell script
        echo "X"
        # x written to handle 1
        cat ext-2.txt
        # fork().
        # parent should wait, child exec's cat.
        # ERROR: parent doesn't wait
        echo "y"
        # y written to handle 1
        # ERROR: child execs cat, cat outputs to handle 1
> > > >

<<<<<<<<<<< strace logs:

<<< good:
### bash 724: parent
###  612 new forked child
  67 7747701 [main] bash 612 fixup_mmaps_after_fork: recreate_mmaps_after_fork, 
mmapped_areas 0x0
  58 7747759 [main] bash 612 sync_with_parent: signalling parent: performed 
fork fixup.
1781 7747826 [main] bash 724 sync_with_child: child signalled me
  81 7747907 [main] bash 724 fork: 612 = fork()
####### fork returns
 121 7748028 [main] bash 724 set_process_mask: old mask = 80002, new mask = 0
 469 7748497 [main] bash 724 set_process_mask: old mask = 0, new mask = 80000
 177 7748674 [main] bash 724 set_process_mask: old mask = 80000, new mask = 0
  57 7748731 [main] bash 724 set_process_mask: old mask = 0, new mask = 80000
  57 7748788 [main] bash 724 sigaction: signal 2, newact 0x22BD20, oldact 
0x22BD10
  64 7748852 [main] bash 724 wait4: calling proc_subproc, pid -1, options 0
  56 7748908 [main] bash 724 proc_subproc: args: 4, 1628200144
  57 7748965 [main] bash 724 proc_subproc: wval->pid -1, wval->options 0
  58 7749023 [main] bash 724 checkstate: nchildren 1, nzombies 0
  54 7749077 [main] bash 724 checkstate: checking alive children
  55 7749132 [main] bash 724 stopped_or_terminated: considering pid 612
  55 7749187 [main] bash 724 checkstate: returning -1
  54 7749241 [main] bash 724 proc_subproc: only found non-terminated children
  55 7749296 [main] bash 724 proc_subproc: finished processing 
terminated/stopped child
### parent waits
  54 7749350 [main] bash 724 proc_subproc: returning 1
1698 7749457 [main] bash 612 MTinterface::fixup_after_fork: mutexs is 0
  61 7749518 [main] bash 612 MTinterface::fixup_after_fork: conds is 0
  55 7749573 [main] bash 612 MTinterface::fixup_after_fork: semaphores is 0
 233 7749806 [main] bash 612 sigproc_init: process/signal handling enabled(801)
  78 7749884 [main] bash 612 fork: 0 = fork()
 173 7750057 [main] bash 612 _close: close (255)
  60 7750117 [main] bash 612 fhandler_base::close: closing '/home/Manfred 
Spraul/cygerror/bad.sh' handle 0xD4
  94 7750211 [main] bash 612 _close: 0 = close (255)
[... snip ...]
 932   20206 [main] cat 612 _pinfo::exit: Calling ExitProcess 0
13297 7795660 [proc] bash 724 proc_subproc: args: 2, 0
 154 7795814 [proc] bash 724 proc_subproc: pid 612[0] terminated, handle 0x138, 
nchildren 1, nzombies 0
  70 7795884 [proc] bash 724 proc_subproc: zombifying [0], pid 612, handle 
0x138, nchildren 1
  61 7795945 [proc] bash 724 proc_subproc: returning 1
  57 7796002 [proc] bash 724 sig_send: pid 724, signal 20, its_me 1
  58 7796060 [proc] bash 724 sig_send: Not waiting for sigcomplete.  its_me 1 
signal 20
  57 7796117 [proc] bash 724 sig_send: returning 0 from sending signal 20
 100 7796217 [sig] bash 724 wait_sig: awake
  70 7796287 [sig] bash 724 wait_sig: signal 20 blocked
  57 7796344 [sig] bash 724 proc_subproc: args: 3, 0
  57 7796401 [sig] bash 724 proc_subproc: looking for processes to reap
  56 7796457 [sig] bash 724 checkstate: nchildren 0, nzombies 1
  56 7796513 [sig] bash 724 stopped_or_terminated: considering pid 612
  65 7796578 [sig] bash 724 remove_zombie: removing 0, pid 612, nzombies 1
 107 7796685 [sig] bash 724 checkstate: returning 1
  61 7796746 [sig] bash 724 proc_subproc: released waiting thread
  56 7796802 [sig] bash 724 proc_subproc: finished processing 
terminated/stopped child
  56 7796858 [sig] bash 724 proc_subproc: returning 1
  55 7796913 [sig] bash 724 wait_sig: looping
  74 7796987 [proc] bash 724 wait_subproc: looping
  80 7797067 [main] bash 724 wait4: 0 = WaitForSingleObject (...)
  80 7797147 [main] bash 724 wait4: intpid -1, status 0x22BD28, w->status 0, 
options 0, res 612
 483 7797630 [main] bash 724 set_process_mask: old mask = 80000, new mask = 0
  65 7797695 [main] bash 724 sig_send: pid 724, signal -2, its_me 1
  67 7797762 [sig] bash 724 wait_sig: awake
  55 7797817 [sig] bash 724 wait_sig: processing signal -2
  55 7797872 [sig] bash 724 wait_sig: processing signal 20
  55 7797927 [sig] bash 724 wait_sig: Got signal 20
  55 7797982 [sig] bash 724 sig_handle: signal 20
  56 7798038 [sig] bash 724 sig_handle: signal 20, about to call 0x41D708
 150 7798188 [sig] bash 724 interruptible: pc 0x610120A3, h 0x61000000, 
interruptible 0, testvalid 0
 100 7798288 [sig] bash 724 interruptible: pc 0x610677B1, h 0x61000000, 
interruptible 0, testvalid 0
 121 7798409 [sig] bash 724 interruptible: pc 0x41CE14, h 0x400000, 
interruptible 1, testvalid 0
  61 7798470 [sig] bash 724 proc_subproc: args: 3, 1
  56 7798526 [sig] bash 724 proc_subproc: clear waiting threads
  55 7798581 [sig] bash 724 proc_subproc: finished clearing
  55 7798636 [sig] bash 724 proc_subproc: returning 1
  58 7798694 [sig] bash 724 interrupt_setup: armed signal_arrived 0xF0, res 1
  55 7798749 [sig] bash 724 setup_handler: good.  Didn't suspend main thread, 
th 0x610C28EC
  56 7798805 [sig] bash 724 setup_handler: returning 1
  55 7798860 [sig] bash 724 sig_handle: returning 1
  54 7798914 [sig] bash 724 proc_subproc: args: 3, 0
  69 7798983 [main] bash 724 sig_send: Waiting for thiscomplete 0xE8
  85 7799068 [sig] bash 724 proc_subproc: looking for processes to reap
  69 7799137 [sig] bash 724 proc_subproc: finished processing 
terminated/stopped child
  71 7799208 [sig] bash 724 proc_subproc: returning 1
  70 7799278 [main] bash 724 sig_send: returning 0 from sending signal -2
  59 7799337 [main] bash 724 reset_signal_arrived: reset signal_arrived
  56 7799393 [main] bash 724 set_process_mask: old mask = 0, new mask = 80000
  58 7799451 [main] bash 724 wait4: calling proc_subproc, pid -1, options 1
  55 7799506 [main] bash 724 proc_subproc: args: 4, 1628200144
  55 7799561 [main] bash 724 proc_subproc: wval->pid -1, wval->options 1
  56 7799617 [main] bash 724 checkstate: nchildren 0, nzombies 0
  55 7799672 [main] bash 724 checkstate: checking alive children
  55 7799727 [main] bash 724 checkstate: returning 0
  59 7799786 [main] bash 724 proc_subproc: waiting thread found no children
  55 7799841 [main] bash 724 proc_subproc: finished processing 
terminated/stopped child
  56 7799897 [main] bash 724 proc_subproc: returning 1
  54 7799951 [main] bash 724 wait4: intpid -1, status 0x22BCC8, w->status 0, 
options 1, res -1
  56 7800007 [main] bash 724 wait4: *** errno = 10
  54 7800061 [main] bash 724 set_process_mask: old mask = 80000, new mask = 0
  57 7800118 [main] bash 724 sigaction: signal 2, newact 0x22BD00, oldact 
0x22BCF0
 643 7800761 [sig] bash 724 wait_sig: set main thread completion event
  65 7800826 [sig] bash 724 wait_sig: looping
1493 7802319 [main] bash 724 _write: write (1, 0xA011EB8, 18)
# next "echo" in the script is executed
<<<

<<< bad
### 1036: new process
### 896: parent
  57 9072870 [main] bash 1036 sync_with_parent: signalling parent: performed 
fork fixup.
1472 9072935 [main] bash 896 sync_with_child: child signalled me
  76 9073011 [main] bash 896 fork: 1036 = fork()
### fork returns to parent
 275 9073145 [main] bash 1036 MTinterface::fixup_after_fork: mutexs is 0
  58 9073203 [main] bash 1036 MTinterface::fixup_after_fork: conds is 0
  54 9073257 [main] bash 1036 MTinterface::fixup_after_fork: semaphores is 0
 216 9073473 [main] bash 1036 sigproc_init: process/signal handling enabled(801)
  85 9073558 [main] bash 1036 fork: 0 = fork()
### client starting
 623 9073634 [main] bash 896 set_process_mask: old mask = 80002, new mask = 0
 532 9074090 [main] bash 1036 _close: close (255)
  65 9074155 [main] bash 1036 fhandler_base::close: closing '/home/Manfred 
Spraul/cygerror/bad.sh' handle 0xD8
  75 9074230 [main] bash 1036 _close: 0 = close (255)
  62 9074292 [main] bash 1036 set_process_mask: old mask = 0, new mask = 0
 385 9074677 [main] bash 1036 set_process_mask: not calling 
sig_dispatch_pending.  sigtid 0x0 current 0x3A8
  66 9074743 [main] bash 1036 sigaction: signal 18, newact 0x22BC60, oldact 
0x22BC50
  58 9074801 [main] bash 1036 sigaction: signal 21, newact 0x22BC50, oldact 
0x22BC40
  56 9074857 [main] bash 1036 sigaction: signal 22, newact 0x22BC60, oldact 
0x22BC50
  60 9074917 [main] bash 1036 sigaction: signal 2, newact 0x22BC40, oldact 
0x22BC30
  60 9074977 [main] bash 1036 sigaction: signal 3, newact 0x22BC40, oldact 
0x22BC30
 403 9075380 [main] bash 1036 sigaction: signal 20, newact 0x22BC40, oldact 
0x22BC30
 131 9075511 [main] bash 1036 spawnve: spawnve (/usr/bin/cat, cat, A016B40)
  61 9075572 [main] bash 1036 spawn_guts: spawn_guts (3, /usr/bin/cat)
  91 9075663 [main] bash 1036 perhaps_suffix: prog '/usr/bin/cat'
 394 9076057 [main] bash 1036 normalize_posix_path: src /usr/bin/cat
  61 9076118 [main] bash 1036 normalize_posix_path: /usr/bin/cat = 
normalize_posix_path (/usr/bin/cat)
  61 9076179 [main] bash 1036 mount_info::conv_to_win32_path: 
conv_to_win32_path (/usr/bin/cat)
  74 9076253 [main] bash 1036 set_flags: flags: binary (0x2)
  56 9076309 [main] bash 1036 mount_info::conv_to_win32_path: src_path 
/usr/bin/cat, dst C:\cygwin\bin\cat, flags 0xA, rc 0
 375 9076684 [main] bash 1036 symlink_info::check: not a symlink
 427 9077111 [main] bash 1036 symlink_info::check: 0 = symlink.check 
(C:\cygwin\bin\cat.exe, 0x22A44C) (0xA)
  82 9077193 [main] bash 1036 path_conv::check: root_dir(C:\), 
this->path(C:\cygwin\bin\cat.exe), set_has_acls(0)
  59 9077252 [main] bash 1036 perhaps_suffix: buf C:\cygwin\bin\cat.exe, suffix 
found '.exe'
 546 9077798 [main] bash 1036 spawn_guts: null_app_name 0 
(C:\cygwin\bin\cat.exe, C:\cygwin\bin\cat.exe ext-2.txt)
  70 9077868 [main] bash 1036 build_env: envp 0xA016B40
  61 9077929 [main] bash 1036 spenv::retrieve: no_envblock 0
  55 9077984 [main] bash 1036 spenv::retrieve: duping existing value for 
'HOMEPATH='
 394 9078378 [main] bash 1036 spenv::retrieve: no_envblock 0
  56 9078434 [main] bash 1036 spenv::retrieve: duping existing value for 
'USERDOMAIN='
  67 9078501 [main] bash 1036 spenv::retrieve: no_envblock 0
  54 9078555 [main] bash 1036 spenv::retrieve: duping existing value for 
'USERNAME='
  60 9078615 [main] bash 1036 spenv::retrieve: no_envblock 0
  55 9078670 [main] bash 1036 spenv::retrieve: no_envblock 0
5189 9078823 [main] bash 896 _write: write (1, 0xA011EB8, 18)
### But: parent doesn't call wait4(), it continues instead!!!
### It seems that is skipped a few syscalls.
### I don't understand why - perhaps longjmp to wrong address, stack corruption
### or bash bug?
  61 9078884 [main] bash 896 fhandler_base::write: binary write
  65 9078949 [main] bash 896 fhandler_base::write: 18 = write (0xA011EB8, 18)
# next "echo" in the script is executed - way too early!
<<<





<<<<<<<<<<<

       The complete logs are ~ 15 MB long, I have them if needed.

Repeat-By:
   unpack the attached tarball, run do-test.sh.
   The bug depends on the timing - 50% reproducable under 
windows+cygwin (script retries until it runs into the bug), no problems 
under Linux.

bug.tar.gz
Description: application/gzip