#755397 glibc FTBFS on alpha: tst-eintr3 sometimes fails.

#755397#5
Date:
2014-07-20 10:26:02 UTC
From:
To:
The test tst-eintr3 sometimes fails in the build of glibc on alpha
and has done so twice in a row in attempting to build 2.19-7.

It's an intermittant fault that appears to only occur on a
multiprocessor SMP system (which the buildd imago is).  Running the
test manually 40 or so times never failed when running a UP kernel.

To make testing faster I have used upstream glibc source on the 2.19
branch configuring with --enable-hardcoded-path-in-tests and running
tst-eintr3 with the --direct option.  It occasionally segfaults.
Getting a core dump and analysing with gdb gives the following:

Core was generated by `/home/mjc/toolchain/glibc-build/nptl/tst-eintr3 --direct'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  start_thread (arg=0x2000121f1f0) at pthread_create.c:243
243	  __resp = &pd->res;

(gdb) bt full
#0  start_thread (arg=0x2000121f1f0) at pthread_create.c:243
        pd = 0x2000121f1f0
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {0 <repeats 17 times>},
              mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x2000003da00 <start_thread>,
              0x2000121f1f0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 252416}}}
        not_first_call = <optimized out>
        robust = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#1  0x0000020000177d24 in thread_start ()
    at ../ports/sysdeps/unix/sysv/linux/alpha/clone.S:111
No locals.

(gdb) disass /m

Dump of assembler code for function start_thread:
232	{
   0x000002000003da00 <+0>:	ldah	gp,3(t12)
   0x000002000003da04 <+4>:	lda	gp,-14800(gp)
   0x000002000003da08 <+8>:	lda	sp,-240(sp)
   0x000002000003da14 <+20>:	stq	fp,40(sp)
   0x000002000003da18 <+24>:	mov	sp,fp
   0x000002000003da24 <+36>:	stq	s0,8(sp)
   0x000002000003da28 <+40>:	stq	ra,0(sp)
   0x000002000003da30 <+48>:	stq	s1,16(sp)
   0x000002000003da38 <+56>:	stq	s2,24(sp)
   0x000002000003da3c <+60>:	stq	s3,32(sp)
   0x000002000003da40 <+64>:	stq	a0,224(fp)

233	  struct pthread *pd = (struct pthread *) arg;
234
235	#if HP_TIMING_AVAIL
236	  /* Remember the time when the thread was started.  */
237	  hp_timing_t now;
238	  HP_TIMING_NOW (now);
239	  THREAD_SETMEM (pd, cpuclock_offset, now);
240	#endif
241
242	  /* Initialize resolver state pointer.  */
243	  __resp = &pd->res;
   0x000002000003da0c <+12>:	rduniq
   0x000002000003da10 <+16>:	ldq	t0,-32656(gp)
   0x000002000003da20 <+32>:	addq	v0,t0,t0
   0x000002000003da2c <+44>:	lda	t1,1208(a0)
   0x000002000003da34 <+52>:	mov	v0,s0
=> 0x000002000003da44 <+68>:	stq	t1,0(t0)


The __resp variable appears to be a thread local variable being
accessed (well, written) by the initial exec TLS model.  The rduniq
PALcall should put the thread pointer (from the PCB) into register
v0.  Now let's check the address being written to at the point of
the segfault.

(gdb) print /x $t0
$1 = 0x18

That's definitely not a valid memory location since the first page of
memory starting at location 0 should be inaccessible.  Checking the
thread pointer:

(gdb) print /x $v0
$2 = 0x0

Ouch!  That looks like the thread pointer in the PCB has not been
initialised.

Running tst-eintr3 under gdb and setting a break point on line 243
reveals that, in general, the rduniq PALcall does return a valid
memory address (and presumably correctly the thread pointer), but,
occassionaly on an SMP system, it can return 0.

This is as far as I have got with debugging.  Presumably there is a
wruniq PALcode call somewhere that sets up the thread pointer in the
PCB and that might be the next place to investigate what is going
on.

Cheers
Michael.

#755397#10
Date:
2014-07-23 08:29:34 UTC
From:
To:
I am starting to think this tst-eintr3 test suite failure on Alpha
might is a kernel bug.  My reasoning goes as follows.

Nowhere does glibc call the wruniq PALcall thus it is not glibc
setting up the thread pointer for a process.  The thread pointer
is passed as an argument to the clone() syscall and it is the
kernel that initialises the process control block (PCB) for a
process and ensures that it is switched in when a process is
scheduled.  That raises the question of whether it might be the
kernel that is failing to correctly initialise the thread pointer
in the PCB.

I therefore ran tst-eintr3 under strace to check that glibc is
calling the clone() syscall correctly.

When tst-eintr3 works correctly the syscall trace is (after deleting
quite a bit of irrelevancy at the start and at the end)

clone(child_stack=0x20000a1eae0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x20000a1f2c0, tls=0x20000a1f8e0, child_tidptr=0x20000a1f2c0) = 20119
--- SIGUSR1 {si_signo=SIGUSR1, si_code=SI_TKILL, si_pid=20118, si_uid=1000} ---
write(1, ".", 1.)                        = 1
sigreturn() (mask [])                   = 20119
mmap(NULL, 8388608, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x20000a20000
mprotect(0x20000a20000, 8192, PROT_NONE) = 0
clone(child_stack=0x2000121eae0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x2000121f2c0, tls=0x2000121f8e0, child_tidptr=0x2000121f2c0) = 20120


In total, clone() gets called twice, and in both cases it looks like
glibc has passed sensible arguments to clone().


Now, the syscall trace for the case when tst-eintr3 segfaults is
illuminating:

clone(child_stack=0x20000a1eae0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x20000a1f2c0, tls=0x20000a1f8e0, child_tidptr=0x20000a1f2c0) = 20087
--- SIGUSR1 {si_signo=SIGUSR1, si_code=SI_TKILL, si_pid=20086, si_uid=1000} ---
write(1, ".", 1.)                        = 1
sigreturn() (mask [])                   = 20087
mmap(NULL, 8388608, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x20000a20000
mprotect(0x20000a20000, 8192, PROT_NONE) = 0
clone(child_stack=0x2000121eae0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x2000121f2c0, tls=0x2000121f8e0, child_tidptr=0x2000121f2c0) = ? ERESTARTNOINTR (To be restarted)
--- SIGUSR1 {si_signo=SIGUSR1, si_code=SI_TKILL, si_pid=20086, si_uid=1000} ---
write(1, ".", 1.)                        = 1
sigreturn() (mask [])                   = -1 ERRNO_312 (Unknown error 312)
clone(child_stack=0x2000121eae0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x2000121f2c0, tls=0, child_tidptr=0x2000121f2c0) = 20089
+++ killed by SIGSEGV +++


The clone() syscall has been tried three times because on the second
time it failed with ERESTARTNOINTR and that particular call has been
retried (the third call to clone() above) with the same arguments except
that the tls argument is now zero!  That error, ERESTARTNOINTR, is a
kernel internal error and should not be visible to userspace.  Indeed,
it is the kernel that retries the clone() syscall as the first try at
running clone() ended up in a mess (something about receiving a signal
right at the worst moment of cloning the process) and the way to
recover is to abandon the clone() function and retry it from the start.

But why is the tls argument zeroed on the retry?  The alpha version of
clone() does not pass the tls argument in the normal way (as a
register). Instead the architecture specific code resorts to finding it
on the stack where the CPU registers were saved on entry to the kernel.
But when an error is returned from a syscall the kernel writes the
stack location for the a3 cpu register with the errno return so that on
final exit from the kernel the a3 cpu register will contain the errno
and then, if appropriate, retries the syscall ensuring the a3 cpu
register has its original contents that it had on entry to the kernel.
But that is no good for the clone() syscall because it ignores the
a3 cpu register (which is the tls argument) and goes to the saved
register on the stack which is by now been changed to zero.  Voila,
a segmentation fault then results in userspace as the thread pointer
is invalid.

I'll take this to linux-alpha and the lkml for thoughts on my analysis
and to work out a solution.

Cheers
Michael.