x/sys/unix: go1.11 on mips64le fails at TestFstatat on Debian build

[anthonyfok]

As of go1.11.4 (1.11.2 and 1.11.4 tested), TestFstatat fails on Debian buildd machines:

--- FAIL: TestFstatat (0.00s)
    syscall_unix_test.go:516: Fstatat: returned stat does not match Stat
    syscall_unix_test.go:535: Fstatat: returned stat does not match Lstat
FAIL
FAIL	cmd/vendor/golang.org/x/sys/unix	0.405s

See https://buildd.debian.org/status/logs.php?pkg=golang-1.11&arch=mips64el for build logs.

Sorry, I haven't found time to try to study this in depth by logging into Debian's remote mips64el (mips64le) machine yet, but thought I should try my luck here first. :-) Many thanks!

[randall77]

Could you change those error generating lines to something like:

t.Errorf("Fstatat: returned stat does not match Stat %#v %#v", st1, st2)

That way we can see what's different about them.

[toddy15]

Here's the output of the both stats:

--- FAIL: TestFstatat (0.00s)
    syscall_unix_test.go:520: Fstatat: returned stat does not match Stat unix.Stat_t{Dev:0x802, Pad1:[3]uint32{0x0, 0x0, 0x0}, Ino:0x4299a, Mode:0x81a4, Nlink:0x1, Uid:0xb67, Gid:0xb67, Rdev:0x0, Pad2:[3]uint32{0x0, 0x0, 0x0}, Size:0, Atim:unix.Timespec{Sec:1545691947, Nsec:449636010}, Mtim:unix.Timespec{Sec:1545691947, Nsec:449636010}, Ctim:unix.Timespec{Sec:1545691947, Nsec:449636010}, Blksize:0x1000, Pad4:0x0, Blocks:0} unix.Stat_t{Dev:0x802, Pad1:[3]uint32{0x0, 0x0, 0x0}, Ino:0x4299a, Mode:0x81a4, Nlink:0x1, Uid:0xb67, Gid:0xb67, Rdev:0x0, Pad2:[3]uint32{0x0, 0x0, 0x0}, Size:0, Atim:unix.Timespec{Sec:1931171959599620907, Nsec:1931171959599620907}, Mtim:unix.Timespec{Sec:1931171959599620907, Nsec:4096}, Ctim:unix.Timespec{Sec:0, Nsec:0}, Blksize:0x0, Pad4:0x0, Blocks:0}
    syscall_unix_test.go:539: Fstatat: returned stat does not match LStat unix.Stat_t{Dev:0x802, Pad1:[3]uint32{0x0, 0x0, 0x0}, Ino:0x4299b, Mode:0xa1ff, Nlink:0x1, Uid:0xb67, Gid:0xb67, Rdev:0x0, Pad2:[3]uint32{0x0, 0x0, 0x0}, Size:5, Atim:unix.Timespec{Sec:1545691947, Nsec:449636010}, Mtim:unix.Timespec{Sec:1545691947, Nsec:449636010}, Ctim:unix.Timespec{Sec:1545691947, Nsec:449636010}, Blksize:0x1000, Pad4:0x0, Blocks:0} unix.Stat_t{Dev:0x802, Pad1:[3]uint32{0x0, 0x0, 0x0}, Ino:0x4299b, Mode:0xa1ff, Nlink:0x1, Uid:0xb67, Gid:0xb67, Rdev:0x0, Pad2:[3]uint32{0x0, 0x0, 0x0}, Size:5, Atim:unix.Timespec{Sec:1931171959599620907, Nsec:1931171959599620907}, Mtim:unix.Timespec{Sec:1931171959599620907, Nsec:4096}, Ctim:unix.Timespec{Sec:0, Nsec:0}, Blksize:0x0, Pad4:0x0, Blocks:0}
FAIL
FAIL	cmd/vendor/golang.org/x/sys/unix	0.409s

It's rather hard to see, but the wdiff boils down to these four members of the structs:

st1:

Atim:unix.Timespec{Sec:1545691947, Nsec:449636010}
Mtim:unix.Timespec{Sec:1545691947, Nsec:449636010}
Ctim:unix.Timespec{Sec:1545691947, Nsec:449636010}
Blksize:0x1000

st2:

Atim:unix.Timespec{Sec:1931171959599620907, Nsec:1931171959599620907}
Mtim:unix.Timespec{Sec:1931171959599620907, Nsec:4096}
Ctim:unix.Timespec{Sec:0, Nsec:0}
Blksize:0x0

The output is the same for the Stat (line 520) and the LStat (line 539) tests.

Hope this helps,
Tobias

[randall77]

It looks the the Fstatat system call is working under the mistaken assumption that the timespecs' fields (seconds and nanoseconds) are only 32 bit. The Go declarations make them 64 bit.
That doesn't seem right. That system call should be writing assuming 64-bit timespec fields. It seems to work on all other architectures.

We might need to do what Stat does, which is to use fillStat_t to convert a stat_t (32-bit) to a Stat_t (64-bit).

It would be good to try to reproduce this using C. I don't understand why mips64le and not (presumably) other architectures.

[randall77]

Try compiling and running this program, and post the output. Also post the output of nm a.out | grep stat.

#include <stdio.h>
#include <sys/stat.h>

int main(int argc, char *argv[]) {
  struct stat s;
  printf("%d\n", sizeof(s.st_atim)); // should be 16                                     
  printf("%d\n", sizeof(s.st_mtim)); // should be 16                                     
  printf("%d\n", sizeof(s.st_ctim)); // should be 16                                     
  stat("/bin/ls", &s);
  printf("%llx %llx\n", s.st_atim.tv_sec, s.st_atim.tv_nsec);
  fstatat(0, "/bin/ls", &s, 0);
  printf("%llx %llx\n", s.st_atim.tv_sec, s.st_atim.tv_nsec);
  return 0;
}

[anthonyfok]

Thank you Randall and Tobias! Merry Christmas!

Try compiling and running this program, and post the output. Also post the output of nm a.out | grep stat.

Here is the result from Debian mipsel/mips64el porterbox eller.debian.org:

(sid_mips64el-dchroot)foka@eller:~/go-issue-29401$ gcc test.c 
(sid_mips64el-dchroot)foka@eller:~/go-issue-29401$ ./a.out 
16
16
16
5c225507 30183b1c
5c225507 30183b1c
(sid_mips64el-dchroot)foka@eller:~/go-issue-29401$ nm a.out | grep stat
                 U __fxstatat@@GLIBC_2.4
0000000000000d80 T __stat
                 U __xstat@@GLIBC_2.0
0000000000000dc0 t fstatat
0000000000000d80 t stat

It probably doesn't matter what specific system type it is, but here is some info:

• Linux eller 4.9.0-8-octeon cmd/cgo: fails with gcc 4.4.1 #1 SMP Debian 4.9.130-2 (2018-10-27) mips64 GNU/Linux
• system type: cavium,rhino_utm8 (CN7030p1.2-1500-AAP)
• cpu model: Cavium Octeon III V0.2 FPU V0.0

Thanks a million!

[randall77]

Looks like stat and fstatat get the right answer when called from C.
There's nothing particularly fishy about the nm output.

It would be interesting to decompile libc for __fxstatat@GLIBC_2.4 and see what system call it boils down to. (Or run the a.out under strace, perhaps.)
Compare that to what Go uses for that call, which is 5252.

Here are the system call numbers we use for that call, by architecture:

syscall/zsysnum_linux_amd64.go:	SYS_NEWFSTATAT             = 262
syscall/zsysnum_linux_mips64.go:	SYS_NEWFSTATAT             = 5252
syscall/zsysnum_linux_mips64le.go:	SYS_NEWFSTATAT             = 5252
syscall/zsysnum_linux_ppc64.go:	SYS_NEWFSTATAT             = 291
syscall/zsysnum_linux_ppc64le.go:	SYS_NEWFSTATAT             = 291
syscall/zsysnum_linux_s390x.go:	SYS_NEWFSTATAT             = 293

It does seem fishy. Maybe we should be using a different system call number for mips64?

[cuonglm]

@randall77 does this fix of musl relate? https://git.musl-libc.org/cgit/musl/commit/?id=4073f03add269be8be9f84d374fe69920b78d53d

[randall77]

@Gnouc That does look very related.
It looks like musl fixed things by working around a kernel bug.
I don't know how musl versioning works, so I'm not sure if their change is applicable to us. Their fix is unconditional on kernel version.
Presumably this bug was introduced at some point, and may be fixed at some point? We'd have to detect the broken kernel version somehow to have a robust fix.

[anthonyfok]

@randall77 Thank you so much for looking further into this issue.

@Gnouc Thank you for the link to a musl fix.

Here is the output of strace ./a.out >& strace.output:

execve("./a.out", ["./a.out"], 0xffff851d60 /* 19 vars */) = 0
brk(NULL)                               = 0xaac0539000
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xfff5c50000
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=15447, ...}) = 0
mmap(NULL, 15447, PROT_READ, MAP_PRIVATE, 3, 0) = 0xfff5c4c000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/mips64el-linux-gnuabi64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0\10\0\1\0\0\0x\331\3\0\0\0\0\0"..., 832) = 832
lseek(3, 63600, SEEK_SET)               = 63600
read(3, "\4\0\0\0\24\0\0\0\3\0\0\0GNU\0L^\n\314O\275Vl\302\27O\221\246\267\210?"..., 36) = 36
lseek(3, 64184, SEEK_SET)               = 64184
read(3, "\4\0\0\0\20\0\0\0\1\0\0\0GNU\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0", 32) = 32
fstat(3, {st_mode=S_IFREG|0755, st_size=1901648, ...}) = 0
mmap(NULL, 1880096, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xfff5a52000
mprotect(0xfff5c00000, 61440, PROT_NONE) = 0
mmap(0xfff5c0f000, 45056, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1ad000) = 0xfff5c0f000
mmap(0xfff5c1a000, 12320, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xfff5c1a000
close(3)                                = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xfff5c4a000
set_thread_area(0xfff5c51720)           = 0
mprotect(0xfff5c0f000, 24576, PROT_READ) = 0
mprotect(0xfff5c54000, 4096, PROT_READ) = 0
munmap(0xfff5c4c000, 15447)             = 0
fstat(1, {st_mode=S_IFREG|0644, st_size=1849, ...}) = 0
brk(NULL)                               = 0xaac0539000
brk(0xaac055a000)                       = 0xaac055a000
stat("/bin/ls", {st_mode=S_IFREG|0755, st_size=190104, ...}) = 0
newfstatat(0, "/bin/ls", {st_mode=S_IFREG|0755, st_size=190104, ...}, 0) = 0
write(1, "16\n16\n16\n5c2525dd b71a9b2\n5c2525"..., 4316
16
16
5c2525dd b71a9b2
5c2525dd b71a9b2
) = 43
exit_group(0)                           = ?
+++ exited with 0 +++

Sorry, I am not sure how to get strace to display the system call number instead of newfstatat.

And here is a quick disassembly of the fstatat() call in the test C program with gdb:

(sid_mips64el-dchroot)foka@eller:~/go-issue-29401$ gdb a.out 
GNU gdb (Debian 8.2-1) 8.2
Copyright (C) 2018 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "mips64el-linux-gnuabi64".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from a.out...done.
(gdb) info line 11
Line 11 of "test.c" starts at address 0xc58 <main+200>
   and ends at 0xc7c <main+236>.
(gdb) disassemble /m 0xc58,0xc7c
Dump of assembler code from 0xc58 to 0xc7c:
11	  fstatat(0, "/bin/ls", &s, 0);
   0x0000000000000c58 <main+200>:	move	a3,zero
   0x0000000000000c5c <main+204>:	move	a2,s8
   0x0000000000000c60 <main+208>:	ld	v0,-32688(gp)
   0x0000000000000c64 <main+212>:	daddiu	a1,v0,3752
   0x0000000000000c68 <main+216>:	move	a0,zero
   0x0000000000000c6c <main+220>:	ld	v0,-32672(gp)
   0x0000000000000c70 <main+224>:	move	t9,v0
   0x0000000000000c74 <main+228>:	bal	0xdc0 <fstatat>
   0x0000000000000c78 <main+232>:	nop

End of assembler dump.
(gdb) 

The corresponding assembly code:

.LVL4 = .
	.loc 1 11 3
	move	$7,$0
	move	$6,$fp
	ld	$2,%got_page(.LC1)($28)
	daddiu	$5,$2,%got_ofst(.LC1)
	move	$4,$0
	ld	$2,%call16(fstatat)($28)
	move	$25,$2
	.reloc	1f,R_MIPS_JALR,fstatat
1:	jalr	$25
	nop

I will see if I can learn how to "decompile libc for __fxstatat@GLIBC_2.4" next. (Sorry, I am still quite a newbie in debugging.) :-)

[anthonyfok]

My first try with disassmbling __fxstatat with GDB:

(sid_mips64el-dchroot)foka@eller:~/debian/glibc-2.28/29401$ gdb ./a.out 
GNU gdb (Debian 8.2-1) 8.2
Copyright (C) 2018 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "mips64el-linux-gnuabi64".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from ./a.out...done.
(gdb) break __fxstatat 
Breakpoint 1 at 0xe20
(gdb) run
Starting program: /home/foka/debian/glibc-2.28/29401/a.out 
16
16
16
5c2525dd b71a9b2

Breakpoint 1, __GI___fxstatat (vers=3, fd=0, file=0xaaaaaaaea8 "/bin/ls", st=0xffffffe3a0, flag=0) at ../sysdeps/unix/sysv/linux/fxstatat.c:38
38	{
(gdb) disassemble /s
Dump of assembler code for function __GI___fxstatat:
../sysdeps/unix/sysv/linux/fxstatat.c:
38	{
=> 0x000000fff7f035b0 <+0>:	daddiu	sp,sp,-144
   0x000000fff7f035b4 <+4>:	sd	gp,128(sp)
   0x000000fff7f035b8 <+8>:	lui	gp,0xc
   0x000000fff7f035bc <+12>:	daddu	gp,gp,t9
   0x000000fff7f035c0 <+16>:	daddiu	gp,gp,16976
   0x000000fff7f035c4 <+20>:	sd	s0,112(sp)
   0x000000fff7f035c8 <+24>:	ld	s0,-22576(gp)
   0x000000fff7f035cc <+28>:	sd	s1,120(sp)
   0x000000fff7f035d0 <+32>:	ld	v0,0(s0)
   0x000000fff7f035d4 <+36>:	move	a5,a0
   0x000000fff7f035d8 <+40>:	move	s1,a3
   0x000000fff7f035dc <+44>:	move	a0,a1
   0x000000fff7f035e0 <+48>:	sd	ra,136(sp)
   0x000000fff7f035e4 <+52>:	move	a1,a2
   0x000000fff7f035e8 <+56>:	sd	v0,104(sp)

39	  int result;
40	  INTERNAL_SYSCALL_DECL (err);
41	#ifdef STAT_IS_KERNEL_STAT
42	# define kst (*st)
43	#else
44	  struct kernel_stat kst;
45	#endif
46	
47	  result = INTERNAL_SYSCALL (newfstatat, err, 4, fd, file, &kst, flag);
   0x000000fff7f035ec <+60>:	move	a3,a4
   0x000000fff7f035f0 <+64>:	move	a2,sp
   0x000000fff7f035f4 <+68>:	li	v0,5252
   0x000000fff7f035f8 <+72>:	syscall

48	  if (!__builtin_expect (INTERNAL_SYSCALL_ERROR_P (result, err), 1))
   0x000000fff7f035fc <+76>:	beqz	a3,0xfff7f03648 <__GI___fxstatat+152>
   0x000000fff7f03600 <+80>:	ld	t9,-26784(gp)
   0x000000fff7f03604 <+84>:	rdhwr	v1,$29
   0x000000fff7f03608 <+88>:	move	a0,v1
   0x000000fff7f0360c <+92>:	ld	v1,-22056(gp)
   0x000000fff7f03610 <+96>:	sll	v0,v0,0x0

54	#endif
55	    }
56	  else
--Type <RET> for more, q to quit, c to continue without paging--c
57	    return INLINE_SYSCALL_ERROR_RETURN_VALUE (INTERNAL_SYSCALL_ERRNO (result,
   0x000000fff7f03614 <+100>:	daddu	v1,v1,a0
   0x000000fff7f03618 <+104>:	sw	v0,0(v1)
   0x000000fff7f0361c <+108>:	li	v0,-1
   0x000000fff7f03620 <+112>:	ld	a0,104(sp)
   0x000000fff7f03624 <+116>:	ld	v1,0(s0)
   0x000000fff7f03628 <+120>:	bne	a0,v1,0xfff7f03660 <__GI___fxstatat+176>
   0x000000fff7f0362c <+124>:	ld	ra,136(sp)
   0x000000fff7f03630 <+128>:	ld	gp,128(sp)
   0x000000fff7f03634 <+132>:	ld	s1,120(sp)
   0x000000fff7f03638 <+136>:	ld	s0,112(sp)
   0x000000fff7f0363c <+140>:	jr	ra
   0x000000fff7f03640 <+144>:	daddiu	sp,sp,144
   0x000000fff7f03644 <+148>:	nop

53	      return __xstat_conv (vers, &kst, st);
   0x000000fff7f03648 <+152>:	move	a1,a2
   0x000000fff7f0364c <+156>:	move	a0,a5
   0x000000fff7f03650 <+160>:	bal	0xfff7f0d450 <__xstat_conv>
   0x000000fff7f03654 <+164>:	move	a2,s1
   0x000000fff7f03658 <+168>:	b	0xfff7f03620 <__GI___fxstatat+112>
   0x000000fff7f0365c <+172>:	nop
   0x000000fff7f03660 <+176>:	ld	t9,-32520(gp)
   0x000000fff7f03664 <+180>:	jalr	t9
   0x000000fff7f03668 <+184>:	nop
End of assembler dump.
(gdb)