Re: 1.3.12-1: bash reorders output

[Manfred Spraul <manfred at colorfullife dot com>]

I've straced the shell script, and it seems that it's either a bash bug
or a memory corruption/longjmp to wrong address with 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: 'cat' is still running and outputs to handle 1
>>>>

I've attached parts of the strace logs below.

In the good case, the child doesn't run until after the parent is 
sleeping, in the bad case, the child runs before the parent has called
wait4().

bash --version reports
<<<
GNU bash, version 2.05b.0(2)-release (i686-pc-cygwin)
Copyright (C) 2002 Free Software Foundation, Inc.

<<<

IIRC there was a linux-kernel/bash problem when the kernel was
modified to run the child process before the parent - perhaps
this is the same probem?

Is someone on the list who remembers the details about that linux/bash bug?
When was it fixed?

--
	Manfred

<<< 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!
 <<<




--
Unsubscribe info:      http://cygwin.com/ml/#unsubscribe-simple
Bug reporting:         http://cygwin.com/bugs.html
Documentation:         http://cygwin.com/docs.html
FAQ:                   http://cygwin.com/faq/