[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.