[parisc-linux] pipes

[parisc-linux] pipes

[Alan Modra]

Would anyone like to hazard a guess as to whether pipes work OK?

The fixincludes problem I'm seeing with devel branch gcc builds looks like
a loss of data in a pipe.  fixincl does a fairly standard trick of opening
a pipe(2) to a fork & exec'd shell, and by putting a little debugging code
in I see some fishy commands in the shell.

Good debug info looks like:

==
case hppa-unknown-linux-gnu in
*-*-sysv4* | \
i?86-*-sysv5* | \
i?86-*-udk* | \
i?86-*-solaris2.[0-4] | \
powerpcle-*-solaris2.[0-4] | \
sparc-*-solaris2.[0-4] )
    echo run ;;
* ) echo skip ;;
esac
==
cd /usr/include
case hppa-unknown-linux-gnu in
*-*-sysv4* | \
i?86-*-sysv5* | \
i?86-*-udk* | \
i?86-*-solaris2.[0-4] | \
powerpcle-*-solaris2.[0-4] | \
sparc-*-solaris2.[0-4] )
    echo run ;;
* ) echo skip ;;
esac

echo
echo ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd

where the first hunk of text between `=='s is wrapped in
`cd /usr/include' .. `echo funky stuff' and plugged into the pipe.  The
hunk of text after the second `==' is what the shell reads from the pipe.
Everything works as expected for a while, and then we get

==
file=sys/stat.h
if ( test  -r types/vxTypesOld.h ) > /dev/null 2>&1
then echo TRUE
else echo FALSE
fi
==
cd /usr/include
file=sys/stat.h
if ( test  -r types/vxTypesOld.h ) > /dev/null 2>&1
then echo TRUE
else echo FALSE
fi
d

Oops, did we just lose 41 chars?

Unfortunately, I'm not sure where the loss happens.  When I tried to
"strace -f -s 256 ...", I ran into

User Fault on Kernel Space pid=319 command='sh'

     YZrvWESTHLNXBCVMcbcbcbcbOGFRQPDI
PSW: 00000000000001000000000000001011
r0-3     00000000 00076808 0002b4c7 00000001
r4-7     401e8648 00000000 0000008b 0007dda8
r8-11    00000001 00076808 0007f008 00078008
r12-15   00076808 00078f02 00076808 bb000ac8
r16-19   00076808 00063800 ffffffff 401e8648
r20-23   000000af 400f0258 0007e498 00000008
r24-27   00000000 bb000ac8 00000002 00076808
r28-31   00000000 00000000 bb000c00 400f027f
sr0-3    0000035e 0000035c 00000000 0000035e
sr4-7    0000035e 0000035e 0000035e 0000035e

IASQ: 00000000 00000000 IAOQ: 400f027f 400f0283
 IIR: 4ad30048    ISR: 0000035e  IOR: 0007e4bc
ORIG_R28: ffffffff

0x400f0270 <__sigprocmask+24>:  stw r3,-3c(sr0,sp)
0x400f0274 <__sigprocmask+28>:  be,l 100(sr2,r0),%sr0,%r31
0x400f0278 <__sigprocmask+32>:  ldi af,r20
0x400f027c <__sigprocmask+36>:  copy ret0,r3

Tried various kernels I built near the end of January, and one dated
20010201 "Linux version 2.4.0-test10 (jsm@forest)" from Matt Taggart.

Time to sleep on it, I think

Alan

Re: [parisc-linux] pipes

[Richard Hirst]

Is this still a problem?

On Sat, Feb 10, 2001 at 02:29:50AM +1100, Alan Modra wrote:
> Would anyone like to hazard a guess as to whether pipes work OK?
> 
> The fixincludes problem I'm seeing with devel branch gcc builds looks like
> a loss of data in a pipe.  fixincl does a fairly standard trick of opening
> a pipe(2) to a fork & exec'd shell, and by putting a little debugging code
> in I see some fishy commands in the shell.
> 
> Good debug info looks like:
> 
> ==
> case hppa-unknown-linux-gnu in
> *-*-sysv4* | \
> i?86-*-sysv5* | \
> i?86-*-udk* | \
> i?86-*-solaris2.[0-4] | \
> powerpcle-*-solaris2.[0-4] | \
> sparc-*-solaris2.[0-4] )
>     echo run ;;
> * ) echo skip ;;
> esac
> ==
> cd /usr/include
> case hppa-unknown-linux-gnu in
> *-*-sysv4* | \
> i?86-*-sysv5* | \
> i?86-*-udk* | \
> i?86-*-solaris2.[0-4] | \
> powerpcle-*-solaris2.[0-4] | \
> sparc-*-solaris2.[0-4] )
>     echo run ;;
> * ) echo skip ;;
> esac
> 
> echo
> echo ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd
> 
> where the first hunk of text between `=='s is wrapped in
> `cd /usr/include' .. `echo funky stuff' and plugged into the pipe.  The
> hunk of text after the second `==' is what the shell reads from the pipe.
> Everything works as expected for a while, and then we get
> 
> ==
> file=sys/stat.h
> if ( test  -r types/vxTypesOld.h ) > /dev/null 2>&1
> then echo TRUE
> else echo FALSE
> fi
> ==
> cd /usr/include
> file=sys/stat.h
> if ( test  -r types/vxTypesOld.h ) > /dev/null 2>&1
> then echo TRUE
> else echo FALSE
> fi
> d
> 
> Oops, did we just lose 41 chars?

Interesting that the loss is from the start of the wrapper text.  Is
the wrapping done in a local buffer and the whole lot written as one
operation to the pipe?  Or is it three seperate writes?

> Unfortunately, I'm not sure where the loss happens.  When I tried to
> "strace -f -s 256 ...", I ran into

Yes, strace -f doesn't seem to work.  I plan to look at that rsn.

Richard

[parisc-linux] Re: pipes

[Alan Modra]

I had another look at the fixincludes problem, and found the following:

14:36:08 write(5, "cd /scsi/tmp\nfile=sys/stat.h\nif ( test  -r types/vxTypesOld.h ) > /dev/null 2>&1\nthen echo TRUE\nelse echo FALSE\nfi\n\necho\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 158) = 158
14:36:08 alarm(10)                      = 0
14:36:08 read(6, "FALSE\n", 4096)       = 6
14:36:08 alarm(10)                      = 10
14:36:08 read(6, "FALSE\nShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 4096) = -512
14:36:18 --- SIGALRM (Alarm clock) ---
14:36:18 read(6, "FALSE\nShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 4096) = -512
14:36:28 --- SIGINT (Interrupt) ---
14:36:28 +++ killed by SIGINT +++

fd 5 and 6 are pipes to a /bin/sh.  -512 is ERESTARTSYS.  ERESTARTSYS
shouldn't happen, and is why fixincludes is bombing.

Nothing suspicious in previous rt_sigaction calls as far as I could see,
and putting in a debugging printk in do_sigaction shows sa_flags is being
set correctly, to 0x40.

Ideas?

Re: [parisc-linux] Re: pipes

[Jes Sorensen]

>>>>> "Alan" == Alan Modra <alan@linuxcare.com.au> writes:

Alan> Nothing suspicious in previous rt_sigaction calls as far as I
Alan> could see, and putting in a debugging printk in do_sigaction
Alan> shows sa_flags is being set correctly, to 0x40.

I'd start by looking at the parisc kernel and glibc implementation of
pipe(). It's a somewhat special system call since it has two return
values.

I managed to wreck pipe() on the ia64 for a while as well.

Jes

Re: [parisc-linux] Re: pipes

[Richard Hirst]

Hi Alan,

On Thu, Feb 22, 2001 at 05:37:55PM +1100, Alan Modra wrote:
> 
> I had another look at the fixincludes problem, and found the following:
> 
> 14:36:08 write(5, "cd /scsi/tmp\nfile=sys/stat.h\nif ( test  -r types/vxTypesOld.h ) > /dev/null 2>&1\nthen echo TRUE\nelse echo FALSE\nfi\n\necho\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 158) = 158
> 14:36:08 alarm(10)                      = 0
> 14:36:08 read(6, "FALSE\n", 4096)       = 6
> 14:36:08 alarm(10)                      = 10
> 14:36:08 read(6, "FALSE\nShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 4096) = -512
> 14:36:18 --- SIGALRM (Alarm clock) ---
> 14:36:18 read(6, "FALSE\nShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 4096) = -512
> 14:36:28 --- SIGINT (Interrupt) ---
> 14:36:28 +++ killed by SIGINT +++
> 
> fd 5 and 6 are pipes to a /bin/sh.  -512 is ERESTARTSYS.  ERESTARTSYS
> shouldn't happen, and is why fixincludes is bombing.
> 
> Nothing suspicious in previous rt_sigaction calls as far as I could see,
> and putting in a debugging printk in do_sigaction shows sa_flags is being
> set correctly, to 0x40.
> 
> Ideas?

Simple test case:

main()
{
        char buf[10];

        strcpy(buf, "my buffer\n");
        alarm(1);
        read(0, buf, 10);
}


10:50:05 alarm(1)                       = 0
10:50:05 read(0, "my buffer\n", 10)     = -512
10:50:06 --- SIGALRM (Alarm clock) ---
10:50:06 +++ killed by SIGALRM +++


Looks like the primary problem is that your read is blocking for 10 seconds
thinking there is no data available.  Secondary problem is that the kernel
returns the wrong thing when the syscall is interrupted.

I gather there is something receiving the data written to fd 5, processing
it, and writing back up fd 6.  We want to know if that something writes
the missing data or not.

Richard

Re: [parisc-linux] Re: pipes

[Richard Hirst]

On Thu, Feb 22, 2001 at 11:00:54AM +0000, Richard Hirst wrote:
> 10:50:05 alarm(1)                       = 0
> 10:50:05 read(0, "my buffer\n", 10)     = -512
> 10:50:06 --- SIGALRM (Alarm clock) ---
> 10:50:06 +++ killed by SIGALRM +++
> 
> 
> Looks like the primary problem is that your read is blocking for 10 seconds
> thinking there is no data available.  Secondary problem is that the kernel
> returns the wrong thing when the syscall is interrupted.

But I just tried this on my x86 as well (2.2 kernel):

alarm(1)                                = 0
read(0, 0xbffff740, 0xa)                = -1 (errno 512)
--- SIGALRM (Alarm clock) ---
+++ killed by SIGALRM +++

Richard

Re: [parisc-linux] Re: pipes

[Alan Cox]

> > thinking there is no data available.  Secondary problem is that the kernel
> > returns the wrong thing when the syscall is interrupted.
> 
> But I just tried this on my x86 as well (2.2 kernel):

The return is ok. Its 'deep magic' strace sees

Re: [parisc-linux] Re: pipes

[Alan Modra]

On Thu, 22 Feb 2001, Richard Hirst wrote:

> On Thu, Feb 22, 2001 at 05:37:55PM +1100, Alan Modra wrote:
> > 
> > I had another look at the fixincludes problem, and found the following:
> > 
> > 14:36:08 write(5, "cd /scsi/tmp\nfile=sys/stat.h\nif ( test  -r types/vxTypesOld.h ) > /dev/null 2>&1\nthen echo TRUE\nelse echo FALSE\nfi\n\necho\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 158) = 158
> > 14:36:08 alarm(10)                      = 0
> > 14:36:08 read(6, "FALSE\n", 4096)       = 6
> > 14:36:08 alarm(10)                      = 10
> > 14:36:08 read(6, "FALSE\nShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 4096) = -512
> > 14:36:18 --- SIGALRM (Alarm clock) ---
> > 14:36:18 read(6, "FALSE\nShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 4096) = -512
> > 14:36:28 --- SIGINT (Interrupt) ---
> > 14:36:28 +++ killed by SIGINT +++
> > 
> > fd 5 and 6 are pipes to a /bin/sh.  -512 is ERESTARTSYS.  ERESTARTSYS
> > shouldn't happen, and is why fixincludes is bombing.
> > 
> > Nothing suspicious in previous rt_sigaction calls as far as I could see,
> > and putting in a debugging printk in do_sigaction shows sa_flags is being
> > set correctly, to 0x40.
> > 
> > Ideas?
> 
> Simple test case:
> 
> main()
> {
>         char buf[10];
> 
>         strcpy(buf, "my buffer\n");
>         alarm(1);
>         read(0, buf, 10);
> }
> 
> 
> 10:50:05 alarm(1)                       = 0
> 10:50:05 read(0, "my buffer\n", 10)     = -512
> 10:50:06 --- SIGALRM (Alarm clock) ---
> 10:50:06 +++ killed by SIGALRM +++
> 
> 
> Looks like the primary problem is that your read is blocking for 10 seconds
> thinking there is no data available.  Secondary problem is that the kernel
> returns the wrong thing when the syscall is interrupted.

Hi Richard,
   This is a different situation.  Notice in my case that the first
read() returning -512 was before the alarm went off.

> I gather there is something receiving the data written to fd 5, processing
> it, and writing back up fd 6.  We want to know if that something writes
> the missing data or not.

Yeah, it's /bin/sh, and has happily executed numerous commands before
the problem occurs.

Alan
-- 

Here's the complete trace.  You can see things are a little different for
the last command sent over the pipe: fixincl has (rather stupidly) decided
to ignore various signals, but that shouldn't make any difference as
regards ERESTARTSYS.  As I said above, I checked what was happening in the
kernel do_sigaction too.

16:30:08 execve("/scsi/tmp/gcc/gcc/fixinc/fixincl", ["/scsi/tmp/gcc/gcc/fixinc/fixincl"], [/* 26 vars */]) = 0
16:31:01 newuname({sys="Linux", node="tea", ...}) = 0
16:30:08 brk(0)                         = 0x18000
16:30:08 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x4001d000
16:30:08 open("/etc/ld.so.preload", O_RDONLY) = -1 ENOENT (No such file or directory)
16:30:08 open("/etc/ld.so.cache", O_RDONLY) = 4
16:30:08 newfstat(4, {st_mode=S_IFREG|0644, st_size=6548, ...}) = 0
16:30:08 mmap(NULL, 6548, PROT_READ, MAP_PRIVATE, 4, 0) = 0x4001e000
16:30:08 close(4)                       = 0
16:30:08 open("/lib/libc.so.6", O_RDONLY) = 4
16:30:08 read(4, "\177ELF\1\2\1\3\0\0\0\0\0\0\0\0\0\3\0\17\0\0\0\1\0\2\202\224\0\0\0004\0N(\300\0\0\2\20\0004\0 \0\5\0(\0E\0B\0\0\0\6\0\0\0004\0\0\0004\0\0\0004\0\0\0\240\0\0\0\240\0\0\0\5\0\0\0\4\0\0\0\3\0\22k(\0\22k(\0\22k(\0\0\0\20\0\0\0\20\0\0\0\4\0\0\0\4\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\22\3618\0\22\3618\0\0\0\5\0\0\20\0\0\0\0\1\0\22\361@\0\23\1@\0\23\1@\0\0\230\304\0\0\316l\0\0\0\7\0\0\20\0\0\0\0\2\0\23\211T\0\23\231T\0\23\231T\0\0\0\260\0\0\0\260\0\0\0\6\0\0\0\4\0\0\3\371\0\0\7\226\0\0\5\373\0\0\2a\0\0\6\302"..., 1024) = 1024
16:30:08 newfstat(4, {st_mode=S_IFREG|0755, st_size=5294284, ...}) = 0
16:30:08 mmap(NULL, 1298348, PROT_READ|PROT_EXEC, MAP_PRIVATE, 4, 0) = 0x40020000
16:30:08 mprotect(0x40150000, 53164, PROT_NONE) = 0
16:30:08 mmap(0x40150000, 40960, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_FIXED, 4, 0x12f000) = 0x40150000
16:30:08 mmap(0x4015a000, 12204, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x4015a000
16:30:08 close(4)                       = 0
16:30:08 munmap(0x4001e000, 6548)       = 0
16:30:08 getpid()                       = 120
16:30:08 brk(0)                         = 0x18000
16:30:08 brk(0x19118)                   = 0x19118
16:30:08 brk(0x1a000)                   = 0x1a000
16:30:08 pipe([4, 5])                   = 0
16:30:08 pipe([6, 7])                   = 0
16:30:08 fork()                         = 121
16:30:08 close(4)                       = 0
16:30:08 close(7)                       = 0
16:30:08 fcntl(6, F_GETFL)              = 0 (flags O_RDONLY)
16:30:08 newfstat(6, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
16:30:08 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x4001e000
16:30:08 _llseek(0x6, 0, 0, 0xfaf00a48, 0x1) = -1 ESPIPE (Illegal seek)
16:30:08 fcntl(5, F_GETFL)              = 0x1 (flags O_WRONLY)
16:30:08 newfstat(5, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
16:30:08 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x4001f000
16:30:08 _llseek(0x5, 0, 0, 0xfaf00a48, 0x1) = -1 ESPIPE (Illegal seek)
16:30:08 getpid()                       = 120
16:30:08 rt_sigaction(SIGPIPE, {0x1664e, [], SA_RESTART}, {SIG_DFL}, 8) = 0
16:30:08 rt_sigaction(SIGALRM, {0x1664e, [], SA_RESTART}, {SIG_DFL}, 8) = 0
16:30:08 write(5, "trap : 1\n", 9)      = 9
16:30:08 brk(0x1c000)                   = 0x1c000
16:30:08 getcwd("/scsi/tmp", 4096)      = 10
16:31:02 write(5, "cd /scsi/tmp\ncase hppa-unknown-linux-gnu in\ni[34567]86-*-linux* )\n    echo run ;;\n* ) echo skip ;;\nesac\n\necho\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 147) = 147
16:30:08 alarm(10)                      = 0
16:30:08 read(6, "skip\n", 4096)        = 5
16:30:09 alarm(10)                      = 10
16:30:09 read(6, "\n", 4096)            = 1
16:30:09 alarm(10)                      = 10
16:30:09 read(6, "ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 4096) = 32
16:30:09 alarm(0)                       = 10
16:30:09 write(5, "cd /scsi/tmp\ncase hppa-unknown-linux-gnu in\ni[34567]86-*-linux* )\n    echo run ;;\n* ) echo skip ;;\nesac\n\necho\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 147) = 147
16:30:09 alarm(10)                      = 0
16:30:09 read(6, "skip\n\nShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 4096) = 38
16:30:09 alarm(10)                      = 10
16:30:09 alarm(10)                      = 10
16:30:09 alarm(0)                       = 10
16:30:09 write(5, "cd /scsi/tmp\ncase hppa-unknown-linux-gnu in\ni[34567]86-*-linux* )\n    echo run ;;\n* ) echo skip ;;\nesac\n\necho\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 147) = 147
16:30:09 alarm(10)                      = 0
16:30:09 read(6, "skip\n\nShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 4096) = 38
16:30:09 alarm(10)                      = 10
16:30:09 alarm(10)                      = 10
16:30:09 alarm(0)                       = 10
16:30:09 write(5, "cd /scsi/tmp\ncase hppa-unknown-linux-gnu in\n*-*-sysv4* | \\\ni[34567]86-*-sysv5* | \\\ni[34567]86-*-udk* | \\\ni[34567]86-*-solaris2.[0-4] | \\\npowerpcle-*-solaris2.[0-4] | \\\nsparc-*-solaris2.[0-4] )\n    echo run ;;\n* ) echo skip ;;\nesac\n\necho\necho ShElL-OuTpUt-H"..., 274) = 274
16:30:09 alarm(10)                      = 0
16:30:09 read(6, "skip\n\nShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 4096) = 38
16:30:09 alarm(10)                      = 10
16:30:09 alarm(10)                      = 10
16:30:09 alarm(0)                       = 10
16:30:09 write(5, "cd /scsi/tmp\ncase hppa-unknown-linux-gnu in\n*-*-ultrix4.3 )\n    echo run ;;\n* ) echo skip ;;\nesac\n\necho\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 141) = 141
16:30:09 alarm(10)                      = 0
16:30:09 read(6, "skip\n\nShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 4096) = 38
16:30:09 alarm(10)                      = 10
16:30:09 alarm(10)                      = 10
16:30:09 alarm(0)                       = 10
16:30:09 write(5, "cd /scsi/tmp\ncase hppa-unknown-linux-gnu in\n*-*-ultrix4.3 )\n    echo run ;;\n* ) echo skip ;;\nesac\n\necho\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 141) = 141
16:30:09 alarm(10)                      = 0
16:30:09 read(6, "skip\n\nShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 4096) = 38
16:30:09 alarm(10)                      = 10
16:30:09 alarm(10)                      = 10
16:30:09 alarm(0)                       = 10
16:30:09 write(5, "cd /scsi/tmp\ncase hppa-unknown-linux-gnu in\n*-*-ultrix4.3 )\n    echo run ;;\n* ) echo skip ;;\nesac\n\necho\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 141) = 141
16:30:09 alarm(10)                      = 0
16:30:09 read(6, "skip\n\nShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 4096) = 38
16:30:09 alarm(10)                      = 10
16:30:09 alarm(10)                      = 10
16:30:09 alarm(0)                       = 10
16:30:09 brk(0x1d000)                   = 0x1d000
16:30:09 brk(0x1e000)                   = 0x1e000
16:30:09 write(5, "cd /scsi/tmp\ncase hppa-unknown-linux-gnu in\nm88k-motorola-sysv3* )\n    echo run ;;\n* ) echo skip ;;\nesac\n\necho\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 148) = 148
16:30:10 alarm(10)                      = 0
16:30:10 read(6, "skip\n\nShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 4096) = 38
16:30:10 alarm(10)                      = 10
16:30:10 alarm(10)                      = 10
16:30:10 alarm(0)                       = 10
16:30:10 brk(0x1f000)                   = 0x1f000
16:30:10 brk(0x20000)                   = 0x20000
16:30:10 write(5, "cd /scsi/tmp\ncase hppa-unknown-linux-gnu in\nm88k-motorola-sysv3* )\n    echo run ;;\n* ) echo skip ;;\nesac\n\necho\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 148) = 148
16:30:10 alarm(10)                      = 0
16:30:10 read(6, "skip\n\nShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 4096) = 38
16:30:10 alarm(10)                      = 10
16:30:10 alarm(10)                      = 10
16:30:10 alarm(0)                       = 10
16:30:10 write(5, "cd /scsi/tmp\ncase hppa-unknown-linux-gnu in\nm88k-*-sysv3* )\n    echo run ;;\n* ) echo skip ;;\nesac\n\necho\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 141) = 141
16:30:10 alarm(10)                      = 0
16:30:10 read(6, "skip\n\nShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 4096) = 38
16:30:10 alarm(10)                      = 10
16:30:10 alarm(10)                      = 10
16:30:10 alarm(0)                       = 10
16:30:10 write(5, "cd /scsi/tmp\ncase hppa-unknown-linux-gnu in\nm88k-tektronix-sysv3* )\n    echo run ;;\n* ) echo skip ;;\nesac\n\necho\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 149) = 149
16:30:10 alarm(10)                      = 0
16:30:10 read(6, "skip\n\nShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 4096) = 38
16:30:10 alarm(10)                      = 10
16:30:10 alarm(10)                      = 10
16:30:10 alarm(0)                       = 10
16:30:10 brk(0x21000)                   = 0x21000
16:30:10 write(5, "cd /scsi/tmp\ncase hppa-unknown-linux-gnu in\nm68k-motorola-sysv* )\n    echo run ;;\n* ) echo skip ;;\nesac\n\necho\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 147) = 147
16:30:10 alarm(10)                      = 0
16:30:10 read(6, "skip\n\nShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 4096) = 38
16:30:10 alarm(10)                      = 10
16:30:10 alarm(10)                      = 10
16:30:10 alarm(0)                       = 10
16:30:10 brk(0x22000)                   = 0x22000
16:30:10 write(5, "cd /scsi/tmp\ncase hppa-unknown-linux-gnu in\ni?86-*-sco3.2* )\n    echo run ;;\n* ) echo skip ;;\nesac\n\necho\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 142) = 142
16:30:10 alarm(10)                      = 0
16:30:10 read(6, "skip\n\nShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 4096) = 38
16:30:10 alarm(10)                      = 10
16:30:10 alarm(10)                      = 10
16:30:10 alarm(0)                       = 10
16:30:10 write(5, "cd /scsi/tmp\ncase hppa-unknown-linux-gnu in\ni?86-*-sco3.2* )\n    echo run ;;\n* ) echo skip ;;\nesac\n\necho\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 142) = 142
16:30:10 alarm(10)                      = 0
16:30:10 read(6, "skip\n\nShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 4096) = 38
16:30:10 alarm(10)                      = 10
16:30:10 alarm(10)                      = 10
16:30:10 alarm(0)                       = 10
16:30:10 write(5, "cd /scsi/tmp\ncase hppa-unknown-linux-gnu in\ni?86-*-sco3.2v4* )\n    echo run ;;\n* ) echo skip ;;\nesac\n\necho\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 144) = 144
16:30:10 alarm(10)                      = 0
16:30:10 read(6, "skip\n\nShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 4096) = 38
16:30:10 alarm(10)                      = 10
16:30:10 alarm(10)                      = 10
16:30:10 alarm(0)                       = 10
16:30:10 brk(0x23000)                   = 0x23000
16:30:10 brk(0x24000)                   = 0x24000
16:30:10 brk(0x25000)                   = 0x25000
16:30:10 write(5, "cd /scsi/tmp\ncase hppa-unknown-linux-gnu in\n*-*-sysv4* | \\\ni?86-*-sysv5* | \\\ni?86-*-udk* | \\\ni?86-*-solaris2.[0-4] | \\\npowerpcle-*-solaris2.[0-4] | \\\nsparc-*-solaris2.[0-4] )\n    echo run ;;\n* ) echo skip ;;\nesac\n\necho\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 256) = 256
16:30:10 alarm(10)                      = 0
16:30:10 read(6, "skip\n\nShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 4096) = 38
16:30:10 alarm(10)                      = 10
16:30:10 alarm(10)                      = 10
16:30:10 alarm(0)                       = 10
16:30:10 brk(0x26000)                   = 0x26000
16:30:10 rt_sigaction(SIGQUIT, {SIG_IGN}, {SIG_DFL}, 8) = 0
16:30:10 rt_sigaction(SIGABRT, {SIG_IGN}, {SIG_DFL}, 8) = 0
16:30:10 rt_sigaction(SIGPIPE, {SIG_IGN}, {0x1664e, [STKFLT RT_2 RT_5 RT_6 RT_8 RT_9 RT_10 RT_12 RT_14 RT_16], SA_RESTART}, 8) = 0
16:30:10 rt_sigaction(SIGALRM, {SIG_IGN}, {0x1664e, [STKFLT RT_2 RT_5 RT_6 RT_8 RT_9 RT_10 RT_12 RT_14 RT_16], SA_RESTART}, 8) = 0
16:30:10 rt_sigaction(SIGTERM, {SIG_IGN}, {SIG_DFL}, 8) = 0
16:30:10 ioctl(2, 0x40245410, {B9600 opost isig icanon echo ...}) = 0
16:30:10 newfstat(0, {st_mode=S_IFIFO|0600, st_size=13, ...}) = 0
16:30:10 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x4015d000
16:30:10 read(0, "./sys/stat.h\n", 4096) = 13
16:30:10 read(0, "", 4096)              = 0
16:30:10 close(0)                       = 0
16:30:10 munmap(0x4015d000, 4096)       = 0
16:30:10 open("/dev/null", O_RDONLY|O_LARGEFILE) = 0
16:30:10 access("sys/stat.h", R_OK)     = 0
16:30:10 newstat("sys/stat.h", {st_mode=S_IFREG|0644, st_size=12006, ...}) = 0
16:30:10 open("sys/stat.h", O_RDONLY)   = 4
16:30:10 mmap(NULL, 12007, PROT_READ, MAP_PRIVATE, 4, 0) = 0x4015d000
16:30:10 write(2, " 12007 sys/stat.h                                           \r", 61) = 61
16:30:10 write(5, "cd /scsi/tmp\nfile=sys/stat.h\nif ( test  -r types/vxTypesOld.h ) > /dev/null 2>&1\nthen echo TRUE\nelse echo FALSE\nfi\n\necho\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 158) = 158
16:30:10 alarm(10)                      = 0
16:30:10 read(6, "FALSE\n", 4096)       = 6
16:30:10 alarm(10)                      = 10
16:30:10 read(6, "FALSE\nShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 4096) = -512
16:30:20 --- SIGALRM (Alarm clock) ---
16:30:20 read(6, "FALSE\nShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 4096) = -512
18:49:04 --- SIGINT (Interrupt) ---
18:49:04 +++ killed by SIGINT +++

Re: [parisc-linux] Re: pipes

[Alan Modra]

On Thu, 22 Feb 2001, Alan Cox wrote:

> > > thinking there is no data available.  Secondary problem is that the kernel
> > > returns the wrong thing when the syscall is interrupted.
> > 
> > But I just tried this on my x86 as well (2.2 kernel):
> 
> The return is ok. Its 'deep magic' strace sees

Err, are you saying I'm barking up the wrong gum tree, and there's nothing
wrong with the read() in my strace output?

Re: [parisc-linux] Re: pipes

[Richard Hirst]

On Thu, Feb 22, 2001 at 10:34:18PM +1100, Alan Modra wrote:
> On Thu, 22 Feb 2001, Richard Hirst wrote:
> 
> > On Thu, Feb 22, 2001 at 05:37:55PM +1100, Alan Modra wrote:
> > > 
> > > I had another look at the fixincludes problem, and found the following:
> > > 
> > > 14:36:08 write(5, "cd /scsi/tmp\nfile=sys/stat.h\nif ( test  -r types/vxTypesOld.h ) > /dev/null 2>&1\nthen echo TRUE\nelse echo FALSE\nfi\n\necho\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 158) = 158
> > > 14:36:08 alarm(10)                      = 0
> > > 14:36:08 read(6, "FALSE\n", 4096)       = 6
> > > 14:36:08 alarm(10)                      = 10
> > > 14:36:08 read(6, "FALSE\nShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 4096) = -512
> > > 14:36:18 --- SIGALRM (Alarm clock) ---
> > > 14:36:18 read(6, "FALSE\nShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 4096) = -512
> > > 14:36:28 --- SIGINT (Interrupt) ---
> > > 14:36:28 +++ killed by SIGINT +++

>    This is a different situation.  Notice in my case that the first
> read() returning -512 was before the alarm went off.

Don't think so.  The read is issued at 14:36:08, no data is available,
so 10 seconds later the alarm goes off, and read returns -512.  Strace
completes that line of output and reports the SIGALRM.

Richard

Re: [parisc-linux] Re: pipes

[Alan Cox]

> > The return is ok. Its 'deep magic' strace sees
> 
> Err, are you saying I'm barking up the wrong gum tree, and there's nothing
> wrong with the read() in my strace output?

strace will see the magic ERESTARTSYS type codes, but the application will not

Re: [parisc-linux] Re: pipes

[Richard Hirst]

On Thu, Feb 22, 2001 at 10:39:57PM +1100, Alan Modra wrote:
> On Thu, 22 Feb 2001, Alan Cox wrote:
> 
> > > > thinking there is no data available.  Secondary problem is that the kernel
> > > > returns the wrong thing when the syscall is interrupted.
> > > 
> > > But I just tried this on my x86 as well (2.2 kernel):
> > 
> > The return is ok. Its 'deep magic' strace sees
> 
> Err, are you saying I'm barking up the wrong gum tree, and there's nothing
> wrong with the read() in my strace output?

I think the problem is simply that there is no data for the read to
pick up, so it hangs until the alarm goes off.

Richard

Re: [parisc-linux] Re: pipes

[Alan Modra]

On Thu, 22 Feb 2001, Richard Hirst wrote:

> Don't think so.  The read is issued at 14:36:08, no data is available,
> so 10 seconds later the alarm goes off, and read returns -512.  Strace
> completes that line of output and reports the SIGALRM.

Ah, thanks for the clarification.  So it comes back to data being mangled
in the pipe or somesuch.

Hmm, strace -f now works with your mods to the kernel, so now I can look
at the other end.  

131   22:37:47 write(5, "cd /scsi/tmp\nfile=sys/stat.h\nif ( test  -r types/vxTypesOld.h ) > /dev/null 2>&1\nthen echo TRUE\nelse echo FALSE\nfi\n\necho\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 158 <unfinished ...>
132   22:37:47 read(0, "cd /scsi/tmp\nfile=sys/stat.h\nif ( test  -r types/vxTypesOld.h ) > /dev/null 2>&1\nthen echo TRUE\nelse echo FALSE\nfi\n\necho\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtEUUUU\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\367\4\0\0\0\0\0PUU\0\0\0\0\0\0"..., 156) = 558544
132   22:37:47 chdir("/scsi/tmp")       = 0

Bingo.  Look at that read.

Re: [parisc-linux] Re: pipes

[Richard Hirst]

On Thu, Feb 22, 2001 at 11:27:14PM +1100, Alan Modra wrote:
> On Thu, 22 Feb 2001, Richard Hirst wrote:
> 
> > Don't think so.  The read is issued at 14:36:08, no data is available,
> > so 10 seconds later the alarm goes off, and read returns -512.  Strace
> > completes that line of output and reports the SIGALRM.
> 
> Ah, thanks for the clarification.  So it comes back to data being mangled
> in the pipe or somesuch.
> 
> Hmm, strace -f now works with your mods to the kernel, so now I can look
> at the other end.  
> 
> 131   22:37:47 write(5, "cd /scsi/tmp\nfile=sys/stat.h\nif ( test  -r types/vxTypesOld.h ) > /dev/null 2>&1\nthen echo TRUE\nelse echo FALSE\nfi\n\necho\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 158 <unfinished ...>
> 132   22:37:47 read(0, "cd /scsi/tmp\nfile=sys/stat.h\nif ( test  -r types/vxTypesOld.h ) > /dev/null 2>&1\nthen echo TRUE\nelse echo FALSE\nfi\n\necho\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtEUUUU\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\367\4\0\0\0\0\0PUU\0\0\0\0\0\0"..., 156) = 558544
> 132   22:37:47 chdir("/scsi/tmp")       = 0
> 
> Bingo.  Look at that read.

Nice one!  I wonder if that <unfinished ...> is significant.  You can
tell strace to write each processes trace to a seperate file, which
might show if that write is really blocked or it is just straces way of
handling output, and you can use -tt to get finer grained timestamping.

How do I reproduce this?  Is it as simple as cd <somewhere in a gcc
build tree> && ./fixincludes, or is it more complex?

Richard

Re: [parisc-linux] Re: pipes

[Alan Modra]

On Thu, 22 Feb 2001, Richard Hirst wrote:

> On Thu, Feb 22, 2001 at 11:27:14PM +1100, Alan Modra wrote:
> > 131   22:37:47 write(5, "cd /scsi/tmp\nfile=sys/stat.h\nif ( test  -r types/vxTypesOld.h ) > /dev/null 2>&1\nthen echo TRUE\nelse echo FALSE\nfi\n\necho\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 158 <unfinished ...>
> > 132   22:37:47 read(0, "cd /scsi/tmp\nfile=sys/stat.h\nif ( test  -r types/vxTypesOld.h ) > /dev/null 2>&1\nthen echo TRUE\nelse echo FALSE\nfi\n\necho\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtEUUUU\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\367\4\0\0\0\0\0PUU\0\0\0\0\0\0"..., 156) = 558544
> > 132   22:37:47 chdir("/scsi/tmp")       = 0
> > 
> > Bingo.  Look at that read.
> 
> Nice one!  I wonder if that <unfinished ...> is significant.

It completes after pid 132 has done a few things.

> How do I reproduce this?  Is it as simple as cd <somewhere in a gcc
> build tree> && ./fixincludes, or is it more complex?

Nothing is ever simple when it comes to gcc ;)

This is more or less what I used for the last trace, but I've
parameterized it for you, and added a crucial mkdir.  Change BUILD to
suit.  What's the betting you can't reproduce this? :-(

BUILD=/scsi/tmp/gcc
mkdir -p $BUILD/gcc/include/usr/include/sys
cd /usr/include
echo ./sys/stat.h | \
TARGET_MACHINE=hppa-unknown-linux-gnu \
ORIGDIR=$BUILD/gcc \
SRCDIR=/usr/include \
INPUT=/usr/include \
DESTDIR=$BUILD/gcc/include \
VERBOSE=5 \
FIND_BASE=. \
strace -s 256 -t -f -o /tmp/tsys $BUILD/gcc/fixinc/fixincl

Re: [parisc-linux] Re: pipes

[Richard Hirst]

On Fri, Feb 23, 2001 at 12:27:44AM +1100, Alan Modra wrote:
> suit.  What's the betting you can't reproduce this? :-(

atm the child dies for me before the two get to talk over the pipes at
all.

Beware: strace output is wrong after a traced program does execve:

main()
{
        execl("/bin/true", "true", 0);
}


...
...
getpid()                                = 13025
execve("/bin/true", ["true"], [/* 20 vars */]) = 0
execve("ê À", [ptrace: umoven: Input/output error
0x1], [/* 1 var */])     = 1073851560
newuname({sys="Linux", node="merlin", ...}) = 0
brk(0)                                  = 0x2f
open("/etc/ld.so.preload", O_RDONLY)    = 9
open("/etc/ld.so.cache", O_RDONLY)      = 3
newfstat(3, {st_mode=S_IFREG|0644, st_size=7103, ...}) = 0
mmap(NULL, 7103, PROT_READ, MAP_PRIVATE, 3, 0) = 0x4001c000
close(3)                                = 1073863222
open("/lib/libc.so.6", O_RDONLY)        = 1073848888
read(3, "\177ELF\1\2\1\3\0\0\0\0\0\0\0\0\0\3\0\17\0\0\0\1\0\2k\314"..., 1024) = 1073856336

Re: [parisc-linux] Re: pipes

[Paul Bame]

I thought I'd write a pipe test program for laughs.  Don't run this
unless you want to cry -- it locks up my machine (both narrow
and wide kernels) after not very many trials, though 'ping' still works.
On a wide kernel, a TOC caught it in __down_interruptible but that
could be normal.

	-P


#include <stdio.h>
#include <unistd.h>

#define READ 0
#define WRITE 1
#define SIZE 4096

int
main(int argc, char *argv[])
{
    int p[2];
    char data[SIZE];
    char rdbuf[SIZE];
    int i;
    int pid;

    if (pipe(p) != 0)
    {
	perror("pipe");
	return 3;
    }

    for (i = 0; i < SIZE; i++)
    {
	data[i] = rand() & 0xff;
    }

    if ((pid = fork()) < 0)
    {
	perror("fork");
	return 3;
    }

    for(i = 0; i < 10000; i++)
    {
	int sendoffset = rand() % SIZE;
	int sendsize = rand() % (SIZE - sendoffset);
	int wr, rd;

	/* Don't bother sending 0 bytes */
	if (sendoffset == SIZE - 1)
	    continue;

	if (pid > 0)
	{
	    wr = write(p[WRITE], data + sendoffset, sendsize);
	    printf("%d: write(data + %d, %d) = %d\n",
		i, sendoffset, sendsize, wr);
	    if (wr != sendsize)
	    {
		fprintf(stderr, "write returns %d expected %d\n", wr, sendsize);
		if (wr < 0)
			perror("write");
	    }
	}
	else
	{
	    rd = read(p[READ], rdbuf, sendsize);
	    printf("%d: read(%d) = %d\n", i, sendsize, rd);
	    if (rd != sendsize)
	    {
		fprintf(stderr, "read returns %d expected %d\n", rd, sendsize);
		if (rd < 0)
		    perror("read");
	    }

	    if (memcmp(data + sendoffset, rdbuf, rd) != 0)
	    {
		fprintf(stderr, "readback compare failed\n");
	    }
	}
    }
}

Re: [parisc-linux] Re: pipes

[Richard Hirst]

On Thu, Feb 22, 2001 at 10:44:02AM -0700, Paul Bame wrote:
> 
> I thought I'd write a pipe test program for laughs.  Don't run this
> unless you want to cry -- it locks up my machine (both narrow
> and wide kernels) after not very many trials, though 'ping' still works.
> On a wide kernel, a TOC caught it in __down_interruptible but that
> could be normal.

Interesting, this kills my almost-cvs-head kernel, but it works
fine on one of my old kernels from Jan 11th.  Sorry Alan, fixincl
fails the same on my Jan 11th kernel.

Also, it works on cvs head under strace, but that kind of synchronises
the two ends of the pipe so you get alternating reads and writes.

Richard

Re: [parisc-linux] Re: pipes

[Alan Modra]

On Fri, 23 Feb 2001, Richard Hirst wrote:

> Also, it works on cvs head under strace, but that kind of synchronises
> the two ends of the pipe so you get alternating reads and writes.

Yes, I found the same result in a test prog I wrote.

Re: [parisc-linux] Re: pipes

[Richard Hirst]

On Fri, Feb 23, 2001 at 10:32:55PM +1100, Alan Modra wrote:
> On Fri, 23 Feb 2001, Richard Hirst wrote:
> 
> > Probably.  Without strace, I now get
> > 
> > merlin:/build# ./fix-bug.sh 
> > /bin/sh: d: command not found                               
> > 
> > 
> > and it hangs with both ends reading their respective pipes.  I guess
> > that indicates I am hitting the same problem as you, anyway.
> 
> This is exactly what I get, right down to the same "d: command not found"

I've added debug to the kernel fs/pipe.c, which shows the problem is
most likely data loss in the child read from the pipe.
The child always issues reads with a 159 byte buffer.  The last write
from the parent is 161 bytes, as can be seen in this strace log:

189   06:24:51 write(5, "cd /usr/include\nfile=sys/stat.h\nif ( test  -r types/vxTypesOld.h ) > /dev/null 2>&1\nthen echo TRUE\nelse echo FALSE\nfi\n\necho\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n", 161) = 161   
190   06:24:51 <... read resumed> "cd /usr/include\nfile=sys/stat.h\nif ( test -r types/vxTypesOld.h ) > /dev/null 2>&1\nthen echo TRUE\nelse echo FALSE\nfi\n\necho\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtE", 159) = 159

(that strace is not from the same run as the debug o/p below, I get
crashes when 190 forks off a child to run the test under strace, so
had to run without strace for the debug below)

and from my debug in the kernel, I see:
(header is pid,inode,r/w,byte-cnt)

189:2504b2a0,write2,259: "cd /usr/include\ncase hppa-unknown-linux-...ho\necho ShElL-OuTpUt-HaS-bEeN-cO
mPlEtEd\n"
190:2504b2a0,read2,159: "cd /usr/include\ncase hppa-unknown-linux-... \\\npowerpcle-*-solaris2.[0-4] | 
\\\nsparc-"
190:2504b2a0,read2,100: "*-solaris2.[0-4] )\n    echo run ;;\n* ) e...ho\necho ShElL-OuTpUt-HaS-bEeN-cO
mPlEtEd\n"
190:2504b0c0,write2,5: "skip\n"
189:2504b0c0,read2,5: "skip\n"
190:2504b0c0,write2,1: "\n"
189:2504b0c0,read2,1: "\n"
190:2504b0c0,write2,32: "ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n"
189:2504b0c0,read2,32: "ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd\n"
189:2504b660,read2,13: "./sys/stat.h\n"
189:2504b2a0,write2,161: "cd /usr/include\nfile=sys/stat.h\nif ( tes...ho\necho ShElL-OuTpUt-HaS-bEeN-c
OmPlEtEd\n"
190:2504b2a0,read2,159: "cd /usr/include\nfile=sys/stat.h\nif ( tes...echo\necho ShElL-OuTpUt-HaS-bEeN-
cOmPlEtE"
190:2504b0c0,write2,6: "FALSE\n"
189:2504b0c0,read2,6: "FALSE\n"
190:2504b2a0,read2,2: "d\n"


so proc 190 reads the following:


cd /usr/include
file=sys/stat.h
if ( test  -r types/vxTypesOld.h ) > /dev/null 2>&1
then echo TRUE
else echo FALSE
fi

echo
echo ShElL-OuTpUt-HaS-bEeN-cOmPlEtE


but there is no 'd\n' at the end of that last line.  Proc 190 does the test,
echoes "FALSE\n", and then goes back to look for more input.  It picks up the
'd\n' and goes trying to find /bin/d, or whatever.  Hence the output we see of


/bin/sh: d: command not found                               



So, I created a /bin/d which contained


#!/bin/sh
echo ShElL-OuTpUt-HaS-bEeN-cOmPlEtEd


and my test script then runs to completion.  The test script is the one
Alan posted, which just runs fixincl on sys/stat.h.

Note that the child only sends "FALSE\n", it doesn't send another "\n",
which should preceed the ShElL-... line.  So, the child is most likely
loosing "echo\necho ShElL-OuTpUt-HaS-bEeN-cOmPlEtE".  41 chars, which is
exactly what Alan reported in the first place.

We do now know that the data is being fed to copy_to_user() in pipe_read(),
and strace shows it is really copied to the users buffer, but it
apparently isn't being seen by the shell on its stdin.

I added more debug to look at buffer alignments, but that didn't show
anything interesting:

Parent write of 161 chars, kernel buffer 0x1dae4000, user buffer 0x4001d000
Child read of 159 bytes,   kernel buffer 0x1dae4000, user buffer 0x00085810

Child input seems to have got lost after 159-41=118 (0x76) chars, or
at child buffer address 0x85886.

So, I used gdb to attach to the stuck child and looked in its buffer:

0x85810:        100 'd' 10 '\n' 32 ' '  47 '/'  117 'u' 115 's' 114 'r' 47 '/'
0x85818:        105 'i' 110 'n' 99 'c'  108 'l' 117 'u' 100 'd' 101 'e' 10 '\n'
0x85820:        102 'f' 105 'i' 108 'l' 101 'e' 61 '='  115 's' 121 'y' 115 's'
0x85828:        47 '/'  115 's' 116 't' 97 'a'  116 't' 46 '.'  104 'h' 10 '\n'
0x85830:        105 'i' 102 'f' 32 ' '  40 '('  32 ' '  116 't' 101 'e' 115 's'
0x85838:        116 't' 32 ' '  32 ' '  45 '-'  114 'r' 32 ' '  116 't' 121 'y'
0x85840:        112 'p' 101 'e' 115 's' 47 '/'  118 'v' 120 'x' 84 'T'  121 'y'
0x85848:        112 'p' 101 'e' 115 's' 79 'O'  108 'l' 100 'd' 46 '.'  104 'h'
0x85850:        32 ' '  41 ')'  32 ' '  62 '>'  32 ' '  47 '/'  100 'd' 101 'e'
0x85858:        118 'v' 47 '/'  110 'n' 117 'u' 108 'l' 108 'l' 32 ' '  50 '2'
0x85860:        62 '>'  38 '&'  49 '1'  10 '\n' 116 't' 104 'h' 101 'e' 110 'n'
0x85868:        32 ' '  101 'e' 99 'c'  104 'h' 111 'o' 32 ' '  84 'T'  82 'R'
0x85870:        85 'U'  69 'E'  10 '\n' 101 'e' 108 'l' 115 's' 101 'e' 32 ' '
0x85878:        101 'e' 99 'c'  104 'h' 111 'o' 32 ' '  70 'F'  65 'A'  76 'L'
0x85880:        83 'S'  69 'E'  10 '\n' 102 'f' 105 'i' 10 '\n' 10 '\n' 101 'e'
0x85888:        99 'c'  104 'h' 111 'o' 10 '\n' 101 'e' 99 'c'  104 'h' 111 'o'
0x85890:        32 ' '  83 'S'  104 'h' 69 'E'  108 'l' 76 'L'  45 '-'  79 'O'
0x85898:        117 'u' 84 'T'  112 'p' 85 'U'  116 't' 45 '-'  72 'H'  97 'a'
0x858a0:        83 'S'  45 '-'  98 'b'  69 'E'  101 'e' 78 'N'  45 '-'  99 'c'
0x858a8:        79 'O'  109 'm' 80 'P'  108 'l' 69 'E'  116 't' 69 'E'  85 'U'
0x858b0:        85 'U'  85 'U'  85 'U'  0 '\000'        0 '\000'        0 '\000'

The data is all there, so now the problem looks like a corrupt return value
from the read().  Should have got 0x9f, appears to have got 0x76.  Except
strace and my kernel debug shows the return value of 0x9f.

Perhaps we should rebuild bash and see if that helps.

Richard

Re: [parisc-linux] Re: pipes

[Richard Hirst]

This is looking like a glibc/kernel issue regardling the width
of the type returned by lseek():


I have a simple way of reproducing the bug now:

merlin:/build# echo 'if ( test  -r /dev/null ); then echo TRUE; fi;
echo Oops' | /bin/sh
TRUE
merlin:/build#


The echo parameter is split over two lines there, and should result
in two lines of output 'TRUE' and then 'Oops'.

/bin/sh picks up input with one read of 57 characters, and then
processes the string, char by char, via input.c:buffered_getchar(),
until it has the complete if..then..fi\n (about 46 characters). Then it
tries to stuff input following the 'fi\n' back on to the input stream by
doing an lseek(fd, -n, SEEK_CUR), before forking a child to do the
'test'.  On return from the child, it expects to pick up the input it
stuffed back on to the input stream.

The problem is that the input stream is a pipe, and lseek doesn't work.
bash should have decided that its input stream was not seekable and
dropped back to multiple reads of one byte.  It uses this test:

#  define fd_is_seekable(fd) (lseek ((fd), 0L, SEEK_CUR) >= 0)

and then

  if (fd_is_seekable (fd) == 0)
    size = 1;
  else
    size = (size_t)((sb.st_size > MAX_INPUT_BUFFER_SIZE) ? ...


Now for us lseek is of type __off64_t (from /usr/include/unistd.h),
although our kernel has sys_lseek() returning off_t, which is 32
bits.  Anyway, if I try to print the 64 bit return value from lseek()
I get 0x00000000ffffffe3.  The lower 32 bits is -ESPIPE, which is the
expected errno.  I don't know if glibc, kernel, or both are at fault
here.

Richard
 

Re: [parisc-linux] Re: pipes

[Matthew Wilcox]

On Mon, Feb 26, 2001 at 05:57:01PM +0000, Richard Hirst wrote:
> Now for us lseek is of type __off64_t (from /usr/include/unistd.h),
> although our kernel has sys_lseek() returning off_t, which is 32
> bits.  Anyway, if I try to print the 64 bit return value from lseek()
> I get 0x00000000ffffffe3.  The lower 32 bits is -ESPIPE, which is the
> expected errno.  I don't know if glibc, kernel, or both are at fault
> here.

Good catch!  The code in sys_lseek seems pretty explicit that it's only
going to return an off_t:

                loff_t res = llseek(file, offset, origin);
                retval = res;
                if (res != (loff_t)retval)
                        retval = -EOVERFLOW;    /* LFS: should only happen on 32
 bit platforms */

and our off_t is:
include/asm-parisc/posix_types.h:typedef long                   __kernel_off_t;

So /usr/include/unistd.h is wrong.  lseek is not 64-bit.

Another way of fixing this would be to make off_t 64-bit... i suspect
that might have performance implications though.

-- 
Revolutions do not require corporate support.