[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
bash-2.05b+cygwin-1.3.12-1: script output is reordered
From: |
Manfred Spraul |
Subject: |
bash-2.05b+cygwin-1.3.12-1: script output is reordered |
Date: |
Mon, 05 Aug 2002 09:10:21 +0200 |
User-agent: |
Mozilla/5.0 (Windows; U; Windows NT 5.0; en-US; rv:1.0.0) Gecko/20020530 |
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
[Prev in Thread] |
Current Thread |
[Next in Thread] |
- bash-2.05b+cygwin-1.3.12-1: script output is reordered,
Manfred Spraul <=