[parisc-linux] Re: pipes

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

[parisc-linux] INLINE_SYSCALL/gcc-bug? (Was Re: pipes)

[Paul Bame]

Help!  Probable gcc bug!

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

To reproduce the bogus return value, compile x.c:

    #include <stdio.h>
    #define __USE_FILE_OFFSET64
    #include <unistd.h>
    #include <errno.h>

    int main(int argc, char *argv[])
    {
	long lwhere = lseek(0, 0L, SEEK_CUR);

	printf("lwhere %lx errno %d (%s)\n", lwhere, errno, sys_errlist[errno]);

	return 0;
    }

then run 'ls | x' which should show 'lwhere' as either 0 or -1, but instead
it's 0xffffffec or something like that (-ESPIPE, as Richard found earlier).

After much head scratching, the bug seems to be occurring in glibc's
INLINE_SYSCALL macro (glibc/sysdeps/unix/sysv/linux/hppa/sysdep.h) as
a result of a compiler bug.  Since INLINE_SYSCALL is used to implement
quite a number of syscalls, this could be a nice thing to fix!  Here's
the "proof".  Consider the ustat() syscall [only because the generated
code is simple, not because it's known to have problems]
glibc/sysdeps/unix/sysv/linux/ustat.c:
    int
    ustat (dev_t dev, struct ustat *ubuf)
    {
      unsigned short int k_dev;

      /* We must convert the value to dev_t type used by the kernel.  */
      k_dev = ((major (dev) & 0xff) << 8) | (minor (dev) & 0xff);

      return INLINE_SYSCALL (ustat, 2, k_dev, CHECK_1 (ubuf));
    }
The way things are supposed to work, INLINE_SYSCALL() tests the value
returned from the kernel syscall, which is either in the range of
-4096..-1, in which case it's an error indicator so errno is set
and INLINE_SYSCALL returns -1 which ustat() then returns (-1 is
the standard syscall error return).  Or if outside this range,
the syscall return value is generally passed back unchanged.  This
logic is apparent from INLINE_SYSCALL:

    #define INLINE_SYSCALL(name, nr, args...)       ({              \
	    unsigned long __sys_res;                                \
	    {                                                       \
		    register unsigned long __res asm("r28");        \
		    LOAD_ARGS_##nr(args)                            \
		    asm volatile(                                   \
			    "ble  0x100(%%sr2, %%r0)\n\t"   \
			    " ldi %1, %%r20"                        \
			    : "=r" (__res)                          \
			    : "i" (SYS_ify(name)) ASM_ARGS_##nr     \
			     );                                     \
		    __sys_res = __res;                              \
	    }                                                       \
	    if (__sys_res >= (unsigned long)-4095) {                \
		    __set_errno(-__sys_res);                        \
		    __sys_res == (unsigned long)-1;                 \
	    }                                                       \
	    __sys_res;                                              \
    })

The symptom is that the return value from INLINE_SYSCALL is never -1
even when the if() condition is true.  It's not even -1 when printf-ed
right after being set to -1.  Here's the generated code for
ustat() plus some comments [xc-latest, latest glibc CVS bits]:

    00000000 <ustat>:
       0:   6b c2 3f d9     stw rp,-14(sr0,sp)
       4:   6f c3 00 80     stw,ma r3,40(sr0,sp)
       8:   08 19 02 56     copy r25,r22
       c:   08 1a 02 57     copy r26,r23
      10:   d2 f6 0a f5     shrpw r22,r23,8,r21
      14:   d6 75 09 18     depw,z r21,23,8,r19
      18:   d2 fa 1b f8     extrw,u r23,31,8,r26
      1c:   08 18 02 59     copy r24,r25
      20:   0b 53 02 5a     or r19,r26,r26
      24:   e4 00 82 00     be,l 100(sr2,r0),%sr0,%r31	# make the syscall
      28:   34 14 00 7c     ldi 3e,r20
      2c:   08 1c 02 43     copy ret0,r3		# save return value
# if (__sys_res >= (unsigned long)-4095)
      30:   34 13 20 01     ldi -1000,r19
      34:   88 73 80 28     cmpb,>>= r19,r3,50 <ustat+0x50>
# {
      38:   08 03 02 5c     copy r3,ret0
      3c:   e8 40 00 00     b,l 44 <ustat+0x44>,rp
			    3c: R_PARISC_PCREL17F   __errno_location
      40:   08 00 02 40     nop
      44:   08 60 04 13     sub r0,r3,r19	 # r19 = -__sys_res
      48:   0f 93 12 80     stw  r19,0(sr0,ret0) # __set_errno(r19)
      4c:   08 03 02 5c     copy r3,ret0	 # restore syscall ret value
# }
      50:   4b c2 3f 59     ldw -54(sr0,sp),rp
      54:   e8 40 c0 00     bv r0(rp)
      58:   4f c3 3f 81     ldw,mb -40(sr0,sp),r3

There appears to be no code generated for setting __sys_res to -1 so
I think this is probably a gcc bug.  I think I confirmed that the bug
exists with no optimization too.

Unfortunately we seem to be working around this bug in
in some of the hppa-specific syscalls, for example hppa/mmap.c
[which is using a poorer algorithm than the one in INLINE_SYSCALL()!]

INLINE_SYSCALL() also has a sign/unsigned problem as willy pointed out.

Attached is a list of glibc source files which contain INLINE_SYSCALL()
so if these syscalls seem broken to you, it could be due to this defect.

./aio_sigqueue.c
./execve.c
./ftruncate64.c
./fxstat.c
./fxstat64.c
./getcwd.c
./getdents.c
./getpriority.c
./llseek.c
./lxstat.c
./lxstat64.c
./msgctl.c
./msgget.c
./msgrcv.c
./msgsnd.c
./poll.c
./pread.c
./pread64.c
./ptrace.c
./pwrite.c
./pwrite64.c
./readv.c
./reboot.c
./semctl.c
./semget.c
./semop.c
./shmat.c
./shmctl.c
./shmdt.c
./shmget.c
./sigaction.c
./sigpending.c
./sigprocmask.c
./sigqueue.c
./sigsuspend.c
./sigtimedwait.c
./sigwaitinfo.c
./sysctl.c
./truncate64.c
./ustat.c
./writev.c
./xmknod.c
./xstat.c
./xstat64.c
./hppa/brk.c
./hppa/mmap.c
./hppa/sysdep.h

Re: [parisc-linux] INLINE_SYSCALL/gcc-bug? (Was Re: pipes)

[Paul Bame]

Minor mistake on my part -- my example wasn't compiled with the latest
compiler but the defect seems stable across several recent compiler
versions (xc-20010305 doesn't appear to be able to compile glob*.c
and others in glibc).

	-P

Re: [parisc-linux] INLINE_SYSCALL/gcc-bug? (Was Re: pipes)

[Jason Eckhardt]

Hi,

On Wed, 7 Mar 2001, Paul Bame wrote:

> 
> Help!  Probable gcc bug!
> 
>     #define INLINE_SYSCALL(name, nr, args...)       ({              \
> 	    unsigned long __sys_res;                                \
> 	    {                                                       \
> 		    register unsigned long __res asm("r28");        \
> 		    LOAD_ARGS_##nr(args)                            \
> 		    asm volatile(                                   \
> 			    "ble  0x100(%%sr2, %%r0)\n\t"   \
> 			    " ldi %1, %%r20"                        \
> 			    : "=r" (__res)                          \
> 			    : "i" (SYS_ify(name)) ASM_ARGS_##nr     \
> 			     );                                     \
> 		    __sys_res = __res;                              \
> 	    }                                                       \
> 	    if (__sys_res >= (unsigned long)-4095) {                \
> 		    __set_errno(-__sys_res);                        \
> 		    __sys_res == (unsigned long)-1;                 \

                             ^^^^
     Perhaps this is why no code is generated to set __sys_res to -1?
     Or am I out of my mind?

     
> 	    }                                                       \
> 	    __sys_res;                                              \
>     })
> 

Re: [parisc-linux] INLINE_SYSCALL/gcc-bug? (Was Re: pipes)

[John David Anglin]

> 		    __set_errno(-__sys_res);                        \
> 		    __sys_res == (unsigned long)-1;                 \
			      ^^
Dave
-- 
J. David Anglin                                  dave.anglin@nrc.ca
National Research Council of Canada              (613) 990-0752 (FAX: 952-6605)