pipes

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

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

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.

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

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

Hi,

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

			      ^^

Dave

J. David Anglin                                  [email protected]
National Research Council of Canada              (613) 990-0752 (FAX: 952-6605)