[LU-11069] ifort lseek returns wrong position on lustre 2.10.3

• Status: Resolved
• Project: Lustre
• Affects Version/s: Lustre 2.12.0, Lustre 2.10.3
• Fix Version/s: Lustre 2.12.0, Lustre 2.10.5
• Type: Bug
• Priority: Critical
• Reporter: Mahmoud Hanafi
• Assignee: John Hammond
• Resolution: Fixed

Environment

sles12 lustre 2.10.3

• Severity: 2

Description

On lustre2.10.3 ifort lseek will return the wrong position when using append ">>" operation.

This can be reproduced on

client: sles12 lustre2.103 <–> server: lustre2.7.3

client: sles12 lustre2.103 <–> server: lustre2.10.3

hello.f

      write(6,*) "hello world"
      end 

Working on sles11 and lustre2.7.3

> date > tt
> date >> tt
> cat tt
Wed May 30 13:32:58 PDT 2018
Wed May 30 13:33:04 PDT 2018
> strace ./a.out >> tt  
.....
ioctl(1, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fffffffbf80) = -1 ENOTTY (Inappropriate ioctl for device)
fstat(1, {st_mode=S_IFREG|0600, st_size=58, ...}) = 0
ioctl(1, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fffffffbf80) = -1 ENOTTY (Inappropriate ioctl for device)
write(1, " hello world\n", 13)          = 13
lseek(1, 0, SEEK_CUR)                   = 71
ftruncate(1, 71)
                        = 0
> cat tt
Wed May 30 13:32:58 PDT 2018
Wed May 30 13:33:04 PDT 2018
 hello world 
 

• • Note lseek(1,0,SEEK_CUR) set at 71.

Not working on lustre2.10.3.

> rm tt
> date > tt
> date >> tt
> cat tt
Wed May 30 13:41:39 PDT 2018
Wed May 30 13:41:44 PDT 2018

> strace ./a.out >> tt   
....
fstat(1, {st_mode=S_IFREG|0600, st_size=58, ...}) = 0
ioctl(1, TCGETS, 0x7fffffffbf80)        = -1 ENOTTY (Inappropriate ioctl for device)
write(1, " hello world\n", 13)          = 13
lseek(1, 0, SEEK_CUR)                   = 13
ftruncate(1, 13)                        = 0

pfe27:/nobackup/jchang> cat tt
Wed May 30 13pfe27:/nobackup/jchang> 
 

*Note that it's lseek that is getting the **wrong* information about current position after the append. 

Issue Links

• is related to: LU-3044 LSeek SEEK_CUR gives incorrect value ...
• is related to: LU-8964 use parallel I/O to improve performan...

Comments

[Nathan Dauchy (Inactive)]

Looks similar to LU-3044 (LSeek SEEK_CUR gives incorrect value after write when file is open with O_APPEND), which was fixed... but perhaps there was a regression in a similar location in the code.

[John Hammond]

This is not limited to ifort and this is on master as well.

n:~# cat test.c
#include <unistd.h>

int main(int argc, char *argv[])
{
	write(1, "Hello world!\n", 13);
	lseek(1, 0, SEEK_CUR);
	ftruncate(1, 13);

	return 0;
}
n:~# gcc -Wall test.c -o test
n:~# cd /mnt/lustre
n:lustre# rm -f f0
n:lustre# date >> f0
n:lustre# date >> f0
n:lustre# cat f0
Sat Jun  2 12:20:11 CDT 2018
Sat Jun  2 12:20:12 CDT 2018
n:lustre# strace ~/test >> f0
execve("/root/test", ["/root/test"], [/* 36 vars */]) = 0
brk(NULL)                               = 0x1c4f000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fd6506da000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=46571, ...}) = 0
mmap(NULL, 46571, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fd6506ce000
close(3)                                = 0
open("/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\20\35\2\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=2127336, ...}) = 0
mmap(NULL, 3940800, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fd6500f7000
mprotect(0x7fd6502af000, 2097152, PROT_NONE) = 0
mmap(0x7fd6504af000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1b8000) = 0x7fd6504af000
mmap(0x7fd6504b5000, 16832, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fd6504b5000
close(3)                                = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fd6506cd000
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fd6506cb000
arch_prctl(ARCH_SET_FS, 0x7fd6506cb740) = 0
mprotect(0x7fd6504af000, 16384, PROT_READ) = 0
mprotect(0x600000, 4096, PROT_READ)     = 0
mprotect(0x7fd6506db000, 4096, PROT_READ) = 0
munmap(0x7fd6506ce000, 46571)           = 0
write(1, "Hello world!\n", 13)          = 13
lseek(1, 0, SEEK_CUR)                   = 13
ftruncate(1, 13)                        = 0
exit_group(0)                           = ?
+++ exited with 0 +++
n:lustre# cat f0
Sat Jun  2 12n:lustre# 

[Andreas Dilger]

Note that the same behaviour with John's test program is seen on both HFS+ and ext4, so it isn't clear if this is really a Lustre bug.

[Andreas Dilger]

Mahmoud, can you please attach your original test program, since I don't think John's is exercising this problem correctly.

[John Hammond]

> Note that the same behaviour with John's test program is seen on both HFS+ and ext4, so it isn't clear if this is really a Lustre bug.

When I run my test program on ext4 (3.10.0-693.11.6.el7.lustre.x86_64) I see the correct behavior:

n:~# cd /tmp
n:tmp# rm -f f0
n:tmp# date >> f0
n:tmp# date >> f0
n:tmp# cat f0
Mon Jun  4 08:28:09 CDT 2018
Mon Jun  4 08:28:10 CDT 2018
n:tmp# strace ~/test >> f0
execve("/root/test", ["/root/test"], [/* 36 vars */]) = 0
brk(NULL)                               = 0x1ccc000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ff77014e000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=46571, ...}) = 0
mmap(NULL, 46571, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7ff770142000
close(3)                                = 0
open("/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\20\35\2\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=2127336, ...}) = 0
mmap(NULL, 3940800, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7ff76fb6b000
mprotect(0x7ff76fd23000, 2097152, PROT_NONE) = 0
mmap(0x7ff76ff23000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1b8000) = 0x7ff76ff23000
mmap(0x7ff76ff29000, 16832, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7ff76ff29000
close(3)                                = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ff770141000
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ff77013f000
arch_prctl(ARCH_SET_FS, 0x7ff77013f740) = 0
mprotect(0x7ff76ff23000, 16384, PROT_READ) = 0
mprotect(0x600000, 4096, PROT_READ)     = 0
mprotect(0x7ff77014f000, 4096, PROT_READ) = 0
munmap(0x7ff770142000, 46571)           = 0
write(1, "Hello world!\n", 13)          = 13
lseek(1, 0, SEEK_CUR)                   = 71
ftruncate(1, 13)                        = 0
exit_group(0)                           = ?
+++ exited with 0 +++

Note that lseek(1, 0, SEEK_CUR) returns 71 (which is correct) rather than 13 as on Lustre.

[Nathan Dauchy (Inactive)]

Andreas, the fortran reproducer is the two line "hello.f" in the original description.

[John Hammond]

Bisection shows that this was introduced by https://review.whamcloud.com/26468 LU-8964 clio: Parallelize generic I/O.

[Andreas Dilger]

My confusion is that I was looking at the file output at the end, which was always truncated, due to the test program calling ftruncate(1, 13) each time. Was that supposed to be ftruncate(1, <lseek_return>) or similar? In any case, just checking the return of lseek() shows that this is indeed a Lustre-specific issue. It would be good to make the test tool check the file size before and after the append and make that clear.

It seems possible to reproduce this problem with multiop instead of making a dedicated test binary for the regression test.

[Mahmoud Hanafi]

Can we expect a patch soon? Or should we pull the offending patch, in our build, until a fix is available.

[John Hammond]

Hi Mahmoud,

I have a patch which passes my version of your test case. (I expect that it will pass yours as well.) I am validating it now.

[Gerrit Updater]

John L. Hammond ([e-mail]) uploaded a new patch: https://review.whamcloud.com/32641
Subject: LU-11069 llite: correct file position after appending writes
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: adb493be610960871720353fdc51b231dd38f976

[Jay Lan (Inactive)]

I have a conflict applying this patch to 2.10.3 at lustre/tests/multiop.c:

int main(int argc, char **argv)
{
char *fname, *commands;
const char *newfile;
const char *oldpath;
struct stat st;
struct statfs stfs;
size_t mmap_len = 0, i;
unsigned char *mmap_ptr = NULL, junk = 0;
int len, fd = -1;
int flags;
int save_errno;
int verbose = 0;
int gid = 0;
lustre_fid fid;
struct timespec ts;
struct lov_user_md_v3 lum;
<<<<<<< HEAD
__u64 dv;
=======
long long rc = 0;
long long last_rc;
>>>>>>> cdad75e521... LU-11069 llite: correct file position after appending writes

 If you agree, I will keep fields dv, rc and last_rc. The 'dv' field might have been removed in master branch in commits that 2.10.3 (b2_10) does not have.

[Andreas Dilger]

Yes, this is no problem. dv was moved to a different part of the file in another patch, but it is harmless to leave this as-is.

[John Hammond]

Hi Jay,

I encourage you to test the patch but please be aware that it has not completed full testing and review. In fact Jinshan pointed out an issue with the first patch set and I have submitted a second patch set. So we would not advise you to put this change into production just yet.

[Jay Lan (Inactive)]

More problems in the patch when cherry-picked to b2_10 without being flagged as conflicts. It then caused compilation errors.

Could you please back port to b2_10? Thanks!

[Gerrit Updater]

John L. Hammond ([e-mail]) uploaded a new patch: https://review.whamcloud.com/32661
Subject: LU-11069 llite: correct file position after appending writes
Project: fs/lustre-release
Branch: b2_10
Current Patch Set: 1
Commit: 1f2e3e935946f02950b67e9359a5d4d28216fbfd

[Jay Lan (Inactive)]

multiop.c: In function 'main':
multiop.c:677:4: error: implicit declaration of function 'llapi_get_ost_layout_v
ersion' [-Werror=implicit-function-declaration]
   rc = llapi_get_ost_layout_version(fd, &layout_version);
   ^
cc1: all warnings being treated as errors
Makefile:1205: recipe for target 'multiop.o' failed
make[5]: *** [multiop.o] Error 1

[John Hammond]

Hi Jay,

A port of the change to b2_10 is available at https://review.whamcloud.com/#/c/32661/2.

[Mahmoud Hanafi]

The patch fixed the lseek issue in our fortran test. When can we expect for it to land.

$ date > tt
$ date >> tt
$ strace ./a.out >> tt

....
ioctl(1, TCGETS, 0x7fffffff77a0)        = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(1, TCGETS, 0x7fffffffbd00)        = -1 ENOTTY (Inappropriate ioctl for device)
fstat(1, {st_mode=S_IFREG|0600, st_size=58, ...}) = 0
ioctl(1, TCGETS, 0x7fffffffbd00)        = -1 ENOTTY (Inappropriate ioctl for device)
write(1, " hello world\n", 13)          = 13
lseek(1, 0, SEEK_CUR)                   = 71
ftruncate(1, 71)                        = 0
.....


$ cat tt
Fri Jun  8 16:00:58 PDT 2018
Fri Jun  8 16:01:01 PDT 2018
 hello world 

[Peter Jones]

Mahmoud

If all goes well it should land to master mid-next week.

Peter

[Gerrit Updater]

Oleg Drokin ([e-mail]) merged in patch https://review.whamcloud.com/32641/
Subject: LU-11069 llite: correct file position after appending writes
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: f8df907e8aaeaee559f913a68a345011a7aa1f23

[Peter Jones]

Landed for 2.12

[Gerrit Updater]

John L. Hammond ([e-mail]) merged in patch https://review.whamcloud.com/32661/
Subject: LU-11069 llite: correct file position after appending writes
Project: fs/lustre-release
Branch: b2_10
Current Patch Set:
Commit: 7bc18a0083b27292dd912dba0ae1aa5010568fb4