* Bug? nfs export on fuse, one more READDIR call after a finished directory read
@ 2019-06-04 10:51 Armin Zentai
2019-06-04 15:12 ` J. Bruce Fields
0 siblings, 1 reply; 4+ messages in thread
From: Armin Zentai @ 2019-06-04 10:51 UTC (permalink / raw)
To: linux-nfs
Hi everyone,
I'm developing a fuse software and it should be able to run _under_ an nfsd export.
Currently I've stripped everything out from the fuse software, and only using it as a mirrorfs. It's written in go and using this lib: https://github.com/hanwen/go-fuse.
My issue a bit complex, but I'll try to explain it as detailed as I can. I like to get some guidance or hint how to proceed with the debugging or a solution of course.
NFS and kernel settings:
client+server: Debian 9.0 / kernel-5.2.0 (I compiled it with debug symbols)
export options: (rw,sync,no_subtree_check,all_squash,anonuid=505,anongid=20,fsid=4193281846142082570)
client mount options: type nfs4 (rw,noatime,vers=4.2,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,timeo=600,retrans=6,sec=sys,clientaddr=10.135.105.205,local_lock=none,addr=10.135.101.174,_netdev)
NFSv3 is explicitly disabled on the server:
cat /proc/fs/nfsd/versions
-2 -3 +4 +4.1 +4.2
The error itself is non-deterministic, but reproducible within ~10 minutes.
Sometimes the client is calling one more READDIR after an empty READDIR reply. The extra READDIR is called with an increased cookie value.
This behaviour is causing an array out-of-bound read in the fuse lib.
This results in an EINVAL error in the go fuse library.
https://github.com/hanwen/go-fuse/blob/master/fuse/nodefs/dir.go#L42
https://github.com/hanwen/go-fuse/blob/master/fuse/nodefs/dir.go#L72
(also there is an open issue by me, https://github.com/hanwen/go-fuse/issues/297)
If this behaviour is totally accepted, then this EINVAL return value can be replaced with fuse.OK in the lib, but I'm a bit curious what is causing this.
The easiest way to reproduce it is using an npm install (without an existing node_modules folder) and in the end it may produce the error.
I haven't debugged the npm install process or reproduced it with a simpler code, but it's happening when removing a directory structure with files.
The npm install at the end removes the fsevents folder with its files. It is downloaded, but not supported on linux (only on OSX) and it removes the module.
So probably it's connected with some npm behaviour which is trying to remove multiple files with multiple async file delete calls.
rm -rf itself can't reproduce the issue.
If I'm running npm install && rm -rf node_modules in a loop, I can reproduce the error in every 2nd - 10th run (approx 2 - 15 minutes).
I've found these things while debugging:
The client is always using readdirplus functions to get directory entries.
If I get a plus=false, then it indicates an error.
Although the error can happen without plus=false too (approx 50/50 chance).
I've used this bpftrace to get it.
```
kprobe:nfs4_xdr_enc_readdir {
$a = ((struct nfs4_readdir_arg *)arg2);
if ($a->plus != 1) {
time("%H:%M:%S\n");
printf("nfs4_xdr_enc_readdir count=%u plus=%u cookie=%llu\n",
$a->count, $a->plus, $a->cookie);
}
}
```
Also there is a kstack, from nfs4_xdr_enc_readdir:
nfs4_xdr_enc_readdir count=262144 plus=0 cookie=24
nfs4_xdr_enc_readdir kstack
nfs4_xdr_enc_readdir+1
rpcauth_wrap_req_encode+35
call_encode+357
__rpc_execute+137
rpc_run_task+268
nfs4_call_sync_sequence+100
_nfs4_proc_readdir+277
nfs4_proc_readdir+141
nfs_readdir_xdr_to_array+375
nfs_readdir+613
iterate_dir+320
__x64_sys_getdents+169
do_syscall_64+85
entry_SYSCALL_64_after_hwframe+68
Also I found out the extra READDIR call, always (mostly?) has an increased (duplicated) dircount parameter.
From wireshark dump there is an example:
Packets from 1 to 4 are totally normal communication.
5-6 are the extra ones.
In packet 3, the dircount is 65536 and in packet 5 it is 131072.
1. client -> server
Remote Procedure Call, Type:Call XID:0x04a37c12
Network File System, Ops(3): SEQUENCE, PUTFH, READDIR
[Program Version: 4]
[V4 Procedure: COMPOUND (1)]
Tag: <EMPTY>
minorversion: 2
Operations (count: 3): SEQUENCE, PUTFH, READDIR
Opcode: SEQUENCE (53)
sessionid: a2fdea5cc954b1470300000000000000
seqid: 0x0001e92f
slot id: 25
high slot id: 25
cache this?: No
Opcode: PUTFH (22)
FileHandle
Opcode: READDIR (26)
cookie: 0
cookie_verf: 0
dircount: 65514
maxcount: 262056
Attr mask[0]: 0x0018091a (Type, Change, Size, FSID, RDAttr_Error, Filehandle, FileId)
Attr mask[1]: 0x00b0a23a (Mode, NumLinks, Owner, Owner_Group, RawDev, Space_Used, Time_Access, Time_Metadata, Time_Modify, Mounted_on_FileId)
[Main Opcode: READDIR (26)]
2. server -> client
Network File System, Ops(3): SEQUENCE PUTFH READDIR
[Program Version: 4]
[V4 Procedure: COMPOUND (1)]
Status: NFS4_OK (0)
Tag: <EMPTY>
Operations (count: 3)
Opcode: SEQUENCE (53)
Status: NFS4_OK (0)
sessionid: a2fdea5cc954b1470300000000000000
seqid: 0x0001e92f
slot id: 25
high slot id: 29
target high slot id: 29
status flags: 0x00000000
Opcode: PUTFH (22)
Status: NFS4_OK (0)
Opcode: READDIR (26)
Status: NFS4_OK (0)
verifier: 0x0000000000000000
Directory Listing
Entry: node-pre-gyp
Entry: needle
Entry: iconv-lite
Entry: readable-stream
Value Follows: No
EOF: Yes
[Main Opcode: READDIR (26)]
3. client -> server
Remote Procedure Call, Type:Call XID:0x16a37c12
Network File System, Ops(3): SEQUENCE, PUTFH, READDIR
[Program Version: 4]
[V4 Procedure: COMPOUND (1)]
Tag: <EMPTY>
minorversion: 2
Operations (count: 3): SEQUENCE, PUTFH, READDIR
Opcode: SEQUENCE (53)
sessionid: a2fdea5cc954b1470300000000000000
seqid: 0x000cd063
slot id: 15
high slot id: 24
cache this?: No
Opcode: PUTFH (22)
FileHandle
Opcode: READDIR (26)
cookie: 6
cookie_verf: 0
dircount: 65536
maxcount: 262144
Attr mask[0]: 0x0018091a (Type, Change, Size, FSID, RDAttr_Error, Filehandle, FileId)
Attr mask[1]: 0x00b0a23a (Mode, NumLinks, Owner, Owner_Group, RawDev, Space_Used, Time_Access, Time_Metadata, Time_Modify, Mounted_on_FileId)
[Main Opcode: READDIR (26)]
4. server -> client
Remote Procedure Call, Type:Reply XID:0x16a37c12
Network File System, Ops(3): SEQUENCE PUTFH READDIR
[Program Version: 4]
[V4 Procedure: COMPOUND (1)]
Status: NFS4_OK (0)
Tag: <EMPTY>
Operations (count: 3)
Opcode: SEQUENCE (53)
Status: NFS4_OK (0)
sessionid: a2fdea5cc954b1470300000000000000
seqid: 0x000cd063
slot id: 15
high slot id: 29
target high slot id: 29
status flags: 0x00000000
Opcode: PUTFH (22)
Status: NFS4_OK (0)
Opcode: READDIR (26)
Status: NFS4_OK (0)
verifier: 0x0000000000000000
Directory Listing
Value Follows: No
EOF: Yes
[Main Opcode: READDIR (26)]
5. client -> server
Remote Procedure Call, Type:Call XID:0x32a37c12
Network File System, Ops(3): SEQUENCE, PUTFH, READDIR
[Program Version: 4]
[V4 Procedure: COMPOUND (1)]
Tag: <EMPTY>
minorversion: 2
Operations (count: 3): SEQUENCE, PUTFH, READDIR
Opcode: SEQUENCE (53)
sessionid: a2fdea5cc954b1470300000000000000
seqid: 0x0001585c
slot id: 26
high slot id: 26
cache this?: No
Opcode: PUTFH (22)
FileHandle
Opcode: READDIR (26)
cookie: 7
cookie_verf: 0
dircount: 131072
maxcount: 262144
Attr mask[0]: 0x00000800 (RDAttr_Error)
Attr mask[1]: 0x00800000 (Mounted_on_FileId)
[Main Opcode: READDIR (26)]
6. server -> client
Remote Procedure Call, Type:Reply XID:0x32a37c12
Network File System, Ops(3): SEQUENCE PUTFH READDIR(NFS4ERR_INVAL)
[Program Version: 4]
[V4 Procedure: COMPOUND (1)]
Status: NFS4ERR_INVAL (22)
Tag: <EMPTY>
Operations (count: 3)
Opcode: SEQUENCE (53)
Status: NFS4_OK (0)
sessionid: a2fdea5cc954b1470300000000000000
seqid: 0x0001585c
slot id: 26
high slot id: 29
target high slot id: 29
status flags: 0x00000000
Opcode: PUTFH (22)
Status: NFS4_OK (0)
Opcode: READDIR (26)
Status: NFS4ERR_INVAL (22)
[Main Opcode: READDIR (26)]
Thanks,
Armin
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: Bug? nfs export on fuse, one more READDIR call after a finished directory read
2019-06-04 10:51 Bug? nfs export on fuse, one more READDIR call after a finished directory read Armin Zentai
@ 2019-06-04 15:12 ` J. Bruce Fields
2019-06-18 0:32 ` Armin Zentai
0 siblings, 1 reply; 4+ messages in thread
From: J. Bruce Fields @ 2019-06-04 15:12 UTC (permalink / raw)
To: Armin Zentai; +Cc: linux-nfs
On Tue, Jun 04, 2019 at 12:51:11PM +0200, Armin Zentai wrote:
> Hi everyone,
>
>
> I'm developing a fuse software and it should be able to run _under_ an nfsd export.
> Currently I've stripped everything out from the fuse software, and only using it as a mirrorfs. It's written in go and using this lib: https://github.com/hanwen/go-fuse.
>
> My issue a bit complex, but I'll try to explain it as detailed as I can. I like to get some guidance or hint how to proceed with the debugging or a solution of course.
>
>
> NFS and kernel settings:
> client+server: Debian 9.0 / kernel-5.2.0 (I compiled it with debug symbols)
> export options: (rw,sync,no_subtree_check,all_squash,anonuid=505,anongid=20,fsid=4193281846142082570)
> client mount options: type nfs4 (rw,noatime,vers=4.2,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,timeo=600,retrans=6,sec=sys,clientaddr=10.135.105.205,local_lock=none,addr=10.135.101.174,_netdev)
>
> NFSv3 is explicitly disabled on the server:
> cat /proc/fs/nfsd/versions
> -2 -3 +4 +4.1 +4.2
>
>
>
> The error itself is non-deterministic, but reproducible within ~10 minutes.
>
> Sometimes the client is calling one more READDIR after an empty READDIR reply. The extra READDIR is called with an increased cookie value.
I don't know why the client's doing that, it does sound a little weird.
I guess the higher cookie value is something cached from a previous
READDIR of the directory. (I think you said it was removing files so
it's not surprising that a cached cookie might point to a position in
the directory that's no longer there.) But I don't know why it would be
issuing another READDIR after the client already set the EOF bit on a
previous one.
Off the top of my head that client behavior sounds weird and suboptimal,
but also harmless.
> This behaviour is causing an array out-of-bound read in the fuse lib.
>
> This results in an EINVAL error in the go fuse library.
> https://github.com/hanwen/go-fuse/blob/master/fuse/nodefs/dir.go#L42
> https://github.com/hanwen/go-fuse/blob/master/fuse/nodefs/dir.go#L72
> (also there is an open issue by me, https://github.com/hanwen/go-fuse/issues/297)
I think that's incorrect.
Assuming the client is using a cookie value that was previously handed
out by the server at some point in the past, the server still needs to
honor that cookie. So it should probably just be returning a succesful
READDIR with zero entries.
--b.
>
> If this behaviour is totally accepted, then this EINVAL return value can be replaced with fuse.OK in the lib, but I'm a bit curious what is causing this.
>
>
>
> The easiest way to reproduce it is using an npm install (without an existing node_modules folder) and in the end it may produce the error.
> I haven't debugged the npm install process or reproduced it with a simpler code, but it's happening when removing a directory structure with files.
> The npm install at the end removes the fsevents folder with its files. It is downloaded, but not supported on linux (only on OSX) and it removes the module.
> So probably it's connected with some npm behaviour which is trying to remove multiple files with multiple async file delete calls.
> rm -rf itself can't reproduce the issue.
>
> If I'm running npm install && rm -rf node_modules in a loop, I can reproduce the error in every 2nd - 10th run (approx 2 - 15 minutes).
>
>
>
> I've found these things while debugging:
>
> The client is always using readdirplus functions to get directory entries.
> If I get a plus=false, then it indicates an error.
> Although the error can happen without plus=false too (approx 50/50 chance).
>
>
> I've used this bpftrace to get it.
>
> ```
> kprobe:nfs4_xdr_enc_readdir {
> $a = ((struct nfs4_readdir_arg *)arg2);
> if ($a->plus != 1) {
> time("%H:%M:%S\n");
> printf("nfs4_xdr_enc_readdir count=%u plus=%u cookie=%llu\n",
> $a->count, $a->plus, $a->cookie);
> }
> }
> ```
>
> Also there is a kstack, from nfs4_xdr_enc_readdir:
>
> nfs4_xdr_enc_readdir count=262144 plus=0 cookie=24
> nfs4_xdr_enc_readdir kstack
>
> nfs4_xdr_enc_readdir+1
> rpcauth_wrap_req_encode+35
> call_encode+357
> __rpc_execute+137
> rpc_run_task+268
> nfs4_call_sync_sequence+100
> _nfs4_proc_readdir+277
> nfs4_proc_readdir+141
> nfs_readdir_xdr_to_array+375
> nfs_readdir+613
> iterate_dir+320
> __x64_sys_getdents+169
> do_syscall_64+85
> entry_SYSCALL_64_after_hwframe+68
>
>
> Also I found out the extra READDIR call, always (mostly?) has an increased (duplicated) dircount parameter.
>
>
> >From wireshark dump there is an example:
>
> Packets from 1 to 4 are totally normal communication.
> 5-6 are the extra ones.
> In packet 3, the dircount is 65536 and in packet 5 it is 131072.
>
>
> 1. client -> server
> Remote Procedure Call, Type:Call XID:0x04a37c12
> Network File System, Ops(3): SEQUENCE, PUTFH, READDIR
> [Program Version: 4]
> [V4 Procedure: COMPOUND (1)]
> Tag: <EMPTY>
> minorversion: 2
> Operations (count: 3): SEQUENCE, PUTFH, READDIR
> Opcode: SEQUENCE (53)
> sessionid: a2fdea5cc954b1470300000000000000
> seqid: 0x0001e92f
> slot id: 25
> high slot id: 25
> cache this?: No
> Opcode: PUTFH (22)
> FileHandle
> Opcode: READDIR (26)
> cookie: 0
> cookie_verf: 0
> dircount: 65514
> maxcount: 262056
> Attr mask[0]: 0x0018091a (Type, Change, Size, FSID, RDAttr_Error, Filehandle, FileId)
> Attr mask[1]: 0x00b0a23a (Mode, NumLinks, Owner, Owner_Group, RawDev, Space_Used, Time_Access, Time_Metadata, Time_Modify, Mounted_on_FileId)
> [Main Opcode: READDIR (26)]
>
> 2. server -> client
> Network File System, Ops(3): SEQUENCE PUTFH READDIR
> [Program Version: 4]
> [V4 Procedure: COMPOUND (1)]
> Status: NFS4_OK (0)
> Tag: <EMPTY>
> Operations (count: 3)
> Opcode: SEQUENCE (53)
> Status: NFS4_OK (0)
> sessionid: a2fdea5cc954b1470300000000000000
> seqid: 0x0001e92f
> slot id: 25
> high slot id: 29
> target high slot id: 29
> status flags: 0x00000000
> Opcode: PUTFH (22)
> Status: NFS4_OK (0)
> Opcode: READDIR (26)
> Status: NFS4_OK (0)
> verifier: 0x0000000000000000
> Directory Listing
> Entry: node-pre-gyp
> Entry: needle
> Entry: iconv-lite
> Entry: readable-stream
> Value Follows: No
> EOF: Yes
> [Main Opcode: READDIR (26)]
>
> 3. client -> server
> Remote Procedure Call, Type:Call XID:0x16a37c12
> Network File System, Ops(3): SEQUENCE, PUTFH, READDIR
> [Program Version: 4]
> [V4 Procedure: COMPOUND (1)]
> Tag: <EMPTY>
> minorversion: 2
> Operations (count: 3): SEQUENCE, PUTFH, READDIR
> Opcode: SEQUENCE (53)
> sessionid: a2fdea5cc954b1470300000000000000
> seqid: 0x000cd063
> slot id: 15
> high slot id: 24
> cache this?: No
> Opcode: PUTFH (22)
> FileHandle
> Opcode: READDIR (26)
> cookie: 6
> cookie_verf: 0
> dircount: 65536
> maxcount: 262144
> Attr mask[0]: 0x0018091a (Type, Change, Size, FSID, RDAttr_Error, Filehandle, FileId)
> Attr mask[1]: 0x00b0a23a (Mode, NumLinks, Owner, Owner_Group, RawDev, Space_Used, Time_Access, Time_Metadata, Time_Modify, Mounted_on_FileId)
> [Main Opcode: READDIR (26)]
>
> 4. server -> client
> Remote Procedure Call, Type:Reply XID:0x16a37c12
> Network File System, Ops(3): SEQUENCE PUTFH READDIR
> [Program Version: 4]
> [V4 Procedure: COMPOUND (1)]
> Status: NFS4_OK (0)
> Tag: <EMPTY>
> Operations (count: 3)
> Opcode: SEQUENCE (53)
> Status: NFS4_OK (0)
> sessionid: a2fdea5cc954b1470300000000000000
> seqid: 0x000cd063
> slot id: 15
> high slot id: 29
> target high slot id: 29
> status flags: 0x00000000
> Opcode: PUTFH (22)
> Status: NFS4_OK (0)
> Opcode: READDIR (26)
> Status: NFS4_OK (0)
> verifier: 0x0000000000000000
> Directory Listing
> Value Follows: No
> EOF: Yes
> [Main Opcode: READDIR (26)]
>
> 5. client -> server
> Remote Procedure Call, Type:Call XID:0x32a37c12
> Network File System, Ops(3): SEQUENCE, PUTFH, READDIR
> [Program Version: 4]
> [V4 Procedure: COMPOUND (1)]
> Tag: <EMPTY>
> minorversion: 2
> Operations (count: 3): SEQUENCE, PUTFH, READDIR
> Opcode: SEQUENCE (53)
> sessionid: a2fdea5cc954b1470300000000000000
> seqid: 0x0001585c
> slot id: 26
> high slot id: 26
> cache this?: No
> Opcode: PUTFH (22)
> FileHandle
> Opcode: READDIR (26)
> cookie: 7
> cookie_verf: 0
> dircount: 131072
> maxcount: 262144
> Attr mask[0]: 0x00000800 (RDAttr_Error)
> Attr mask[1]: 0x00800000 (Mounted_on_FileId)
> [Main Opcode: READDIR (26)]
>
> 6. server -> client
> Remote Procedure Call, Type:Reply XID:0x32a37c12
> Network File System, Ops(3): SEQUENCE PUTFH READDIR(NFS4ERR_INVAL)
> [Program Version: 4]
> [V4 Procedure: COMPOUND (1)]
> Status: NFS4ERR_INVAL (22)
> Tag: <EMPTY>
> Operations (count: 3)
> Opcode: SEQUENCE (53)
> Status: NFS4_OK (0)
> sessionid: a2fdea5cc954b1470300000000000000
> seqid: 0x0001585c
> slot id: 26
> high slot id: 29
> target high slot id: 29
> status flags: 0x00000000
> Opcode: PUTFH (22)
> Status: NFS4_OK (0)
> Opcode: READDIR (26)
> Status: NFS4ERR_INVAL (22)
> [Main Opcode: READDIR (26)]
>
>
> Thanks,
> Armin
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: Bug? nfs export on fuse, one more READDIR call after a finished directory read
2019-06-04 15:12 ` J. Bruce Fields
@ 2019-06-18 0:32 ` Armin Zentai
2019-06-18 17:58 ` J. Bruce Fields
0 siblings, 1 reply; 4+ messages in thread
From: Armin Zentai @ 2019-06-18 0:32 UTC (permalink / raw)
To: J. Bruce Fields; +Cc: linux-nfs
After, I've done some tests, I confirmed, you were right.
I was able to reproduce the issue with a very simple example code
- create a few hundred folders within a folder
- using the example code with a smaller BUF_SIZE, like 256, http://man7.org/linux/man-pages/man2/getdents.2.html
- also deleting one folder in every iteration of the outer for loop
This clearly reproduces the issue and the fuse lib's EINVAL is a false-positive error and it should return a simple empty array with fuse.OK return code.
Thanks,
Armin
> On 2019. Jun 4., at 17:12, J. Bruce Fields <bfields@fieldses.org> wrote:
>
> On Tue, Jun 04, 2019 at 12:51:11PM +0200, Armin Zentai wrote:
>> Hi everyone,
>>
>>
>> I'm developing a fuse software and it should be able to run _under_ an nfsd export.
>> Currently I've stripped everything out from the fuse software, and only using it as a mirrorfs. It's written in go and using this lib: https://github.com/hanwen/go-fuse.
>>
>> My issue a bit complex, but I'll try to explain it as detailed as I can. I like to get some guidance or hint how to proceed with the debugging or a solution of course.
>>
>>
>> NFS and kernel settings:
>> client+server: Debian 9.0 / kernel-5.2.0 (I compiled it with debug symbols)
>> export options: (rw,sync,no_subtree_check,all_squash,anonuid=505,anongid=20,fsid=4193281846142082570)
>> client mount options: type nfs4 (rw,noatime,vers=4.2,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,timeo=600,retrans=6,sec=sys,clientaddr=10.135.105.205,local_lock=none,addr=10.135.101.174,_netdev)
>>
>> NFSv3 is explicitly disabled on the server:
>> cat /proc/fs/nfsd/versions
>> -2 -3 +4 +4.1 +4.2
>>
>>
>>
>> The error itself is non-deterministic, but reproducible within ~10 minutes.
>>
>> Sometimes the client is calling one more READDIR after an empty READDIR reply. The extra READDIR is called with an increased cookie value.
>
> I don't know why the client's doing that, it does sound a little weird.
> I guess the higher cookie value is something cached from a previous
> READDIR of the directory. (I think you said it was removing files so
> it's not surprising that a cached cookie might point to a position in
> the directory that's no longer there.) But I don't know why it would be
> issuing another READDIR after the client already set the EOF bit on a
> previous one.
>
> Off the top of my head that client behavior sounds weird and suboptimal,
> but also harmless.
>
>> This behaviour is causing an array out-of-bound read in the fuse lib.
>>
>> This results in an EINVAL error in the go fuse library.
>> https://github.com/hanwen/go-fuse/blob/master/fuse/nodefs/dir.go#L42
>> https://github.com/hanwen/go-fuse/blob/master/fuse/nodefs/dir.go#L72
>> (also there is an open issue by me, https://github.com/hanwen/go-fuse/issues/297)
>
> I think that's incorrect.
>
> Assuming the client is using a cookie value that was previously handed
> out by the server at some point in the past, the server still needs to
> honor that cookie. So it should probably just be returning a succesful
> READDIR with zero entries.
>
> --b.
>
>
>>
>> If this behaviour is totally accepted, then this EINVAL return value can be replaced with fuse.OK in the lib, but I'm a bit curious what is causing this.
>>
>>
>>
>> The easiest way to reproduce it is using an npm install (without an existing node_modules folder) and in the end it may produce the error.
>> I haven't debugged the npm install process or reproduced it with a simpler code, but it's happening when removing a directory structure with files.
>> The npm install at the end removes the fsevents folder with its files. It is downloaded, but not supported on linux (only on OSX) and it removes the module.
>> So probably it's connected with some npm behaviour which is trying to remove multiple files with multiple async file delete calls.
>> rm -rf itself can't reproduce the issue.
>>
>> If I'm running npm install && rm -rf node_modules in a loop, I can reproduce the error in every 2nd - 10th run (approx 2 - 15 minutes).
>>
>>
>>
>> I've found these things while debugging:
>>
>> The client is always using readdirplus functions to get directory entries.
>> If I get a plus=false, then it indicates an error.
>> Although the error can happen without plus=false too (approx 50/50 chance).
>>
>>
>> I've used this bpftrace to get it.
>>
>> ```
>> kprobe:nfs4_xdr_enc_readdir {
>> $a = ((struct nfs4_readdir_arg *)arg2);
>> if ($a->plus != 1) {
>> time("%H:%M:%S\n");
>> printf("nfs4_xdr_enc_readdir count=%u plus=%u cookie=%llu\n",
>> $a->count, $a->plus, $a->cookie);
>> }
>> }
>> ```
>>
>> Also there is a kstack, from nfs4_xdr_enc_readdir:
>>
>> nfs4_xdr_enc_readdir count=262144 plus=0 cookie=24
>> nfs4_xdr_enc_readdir kstack
>>
>> nfs4_xdr_enc_readdir+1
>> rpcauth_wrap_req_encode+35
>> call_encode+357
>> __rpc_execute+137
>> rpc_run_task+268
>> nfs4_call_sync_sequence+100
>> _nfs4_proc_readdir+277
>> nfs4_proc_readdir+141
>> nfs_readdir_xdr_to_array+375
>> nfs_readdir+613
>> iterate_dir+320
>> __x64_sys_getdents+169
>> do_syscall_64+85
>> entry_SYSCALL_64_after_hwframe+68
>>
>>
>> Also I found out the extra READDIR call, always (mostly?) has an increased (duplicated) dircount parameter.
>>
>>
>>> From wireshark dump there is an example:
>>
>> Packets from 1 to 4 are totally normal communication.
>> 5-6 are the extra ones.
>> In packet 3, the dircount is 65536 and in packet 5 it is 131072.
>>
>>
>> 1. client -> server
>> Remote Procedure Call, Type:Call XID:0x04a37c12
>> Network File System, Ops(3): SEQUENCE, PUTFH, READDIR
>> [Program Version: 4]
>> [V4 Procedure: COMPOUND (1)]
>> Tag: <EMPTY>
>> minorversion: 2
>> Operations (count: 3): SEQUENCE, PUTFH, READDIR
>> Opcode: SEQUENCE (53)
>> sessionid: a2fdea5cc954b1470300000000000000
>> seqid: 0x0001e92f
>> slot id: 25
>> high slot id: 25
>> cache this?: No
>> Opcode: PUTFH (22)
>> FileHandle
>> Opcode: READDIR (26)
>> cookie: 0
>> cookie_verf: 0
>> dircount: 65514
>> maxcount: 262056
>> Attr mask[0]: 0x0018091a (Type, Change, Size, FSID, RDAttr_Error, Filehandle, FileId)
>> Attr mask[1]: 0x00b0a23a (Mode, NumLinks, Owner, Owner_Group, RawDev, Space_Used, Time_Access, Time_Metadata, Time_Modify, Mounted_on_FileId)
>> [Main Opcode: READDIR (26)]
>>
>> 2. server -> client
>> Network File System, Ops(3): SEQUENCE PUTFH READDIR
>> [Program Version: 4]
>> [V4 Procedure: COMPOUND (1)]
>> Status: NFS4_OK (0)
>> Tag: <EMPTY>
>> Operations (count: 3)
>> Opcode: SEQUENCE (53)
>> Status: NFS4_OK (0)
>> sessionid: a2fdea5cc954b1470300000000000000
>> seqid: 0x0001e92f
>> slot id: 25
>> high slot id: 29
>> target high slot id: 29
>> status flags: 0x00000000
>> Opcode: PUTFH (22)
>> Status: NFS4_OK (0)
>> Opcode: READDIR (26)
>> Status: NFS4_OK (0)
>> verifier: 0x0000000000000000
>> Directory Listing
>> Entry: node-pre-gyp
>> Entry: needle
>> Entry: iconv-lite
>> Entry: readable-stream
>> Value Follows: No
>> EOF: Yes
>> [Main Opcode: READDIR (26)]
>>
>> 3. client -> server
>> Remote Procedure Call, Type:Call XID:0x16a37c12
>> Network File System, Ops(3): SEQUENCE, PUTFH, READDIR
>> [Program Version: 4]
>> [V4 Procedure: COMPOUND (1)]
>> Tag: <EMPTY>
>> minorversion: 2
>> Operations (count: 3): SEQUENCE, PUTFH, READDIR
>> Opcode: SEQUENCE (53)
>> sessionid: a2fdea5cc954b1470300000000000000
>> seqid: 0x000cd063
>> slot id: 15
>> high slot id: 24
>> cache this?: No
>> Opcode: PUTFH (22)
>> FileHandle
>> Opcode: READDIR (26)
>> cookie: 6
>> cookie_verf: 0
>> dircount: 65536
>> maxcount: 262144
>> Attr mask[0]: 0x0018091a (Type, Change, Size, FSID, RDAttr_Error, Filehandle, FileId)
>> Attr mask[1]: 0x00b0a23a (Mode, NumLinks, Owner, Owner_Group, RawDev, Space_Used, Time_Access, Time_Metadata, Time_Modify, Mounted_on_FileId)
>> [Main Opcode: READDIR (26)]
>>
>> 4. server -> client
>> Remote Procedure Call, Type:Reply XID:0x16a37c12
>> Network File System, Ops(3): SEQUENCE PUTFH READDIR
>> [Program Version: 4]
>> [V4 Procedure: COMPOUND (1)]
>> Status: NFS4_OK (0)
>> Tag: <EMPTY>
>> Operations (count: 3)
>> Opcode: SEQUENCE (53)
>> Status: NFS4_OK (0)
>> sessionid: a2fdea5cc954b1470300000000000000
>> seqid: 0x000cd063
>> slot id: 15
>> high slot id: 29
>> target high slot id: 29
>> status flags: 0x00000000
>> Opcode: PUTFH (22)
>> Status: NFS4_OK (0)
>> Opcode: READDIR (26)
>> Status: NFS4_OK (0)
>> verifier: 0x0000000000000000
>> Directory Listing
>> Value Follows: No
>> EOF: Yes
>> [Main Opcode: READDIR (26)]
>>
>> 5. client -> server
>> Remote Procedure Call, Type:Call XID:0x32a37c12
>> Network File System, Ops(3): SEQUENCE, PUTFH, READDIR
>> [Program Version: 4]
>> [V4 Procedure: COMPOUND (1)]
>> Tag: <EMPTY>
>> minorversion: 2
>> Operations (count: 3): SEQUENCE, PUTFH, READDIR
>> Opcode: SEQUENCE (53)
>> sessionid: a2fdea5cc954b1470300000000000000
>> seqid: 0x0001585c
>> slot id: 26
>> high slot id: 26
>> cache this?: No
>> Opcode: PUTFH (22)
>> FileHandle
>> Opcode: READDIR (26)
>> cookie: 7
>> cookie_verf: 0
>> dircount: 131072
>> maxcount: 262144
>> Attr mask[0]: 0x00000800 (RDAttr_Error)
>> Attr mask[1]: 0x00800000 (Mounted_on_FileId)
>> [Main Opcode: READDIR (26)]
>>
>> 6. server -> client
>> Remote Procedure Call, Type:Reply XID:0x32a37c12
>> Network File System, Ops(3): SEQUENCE PUTFH READDIR(NFS4ERR_INVAL)
>> [Program Version: 4]
>> [V4 Procedure: COMPOUND (1)]
>> Status: NFS4ERR_INVAL (22)
>> Tag: <EMPTY>
>> Operations (count: 3)
>> Opcode: SEQUENCE (53)
>> Status: NFS4_OK (0)
>> sessionid: a2fdea5cc954b1470300000000000000
>> seqid: 0x0001585c
>> slot id: 26
>> high slot id: 29
>> target high slot id: 29
>> status flags: 0x00000000
>> Opcode: PUTFH (22)
>> Status: NFS4_OK (0)
>> Opcode: READDIR (26)
>> Status: NFS4ERR_INVAL (22)
>> [Main Opcode: READDIR (26)]
>>
>>
>> Thanks,
>> Armin
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: Bug? nfs export on fuse, one more READDIR call after a finished directory read
2019-06-18 0:32 ` Armin Zentai
@ 2019-06-18 17:58 ` J. Bruce Fields
0 siblings, 0 replies; 4+ messages in thread
From: J. Bruce Fields @ 2019-06-18 17:58 UTC (permalink / raw)
To: Armin Zentai; +Cc: linux-nfs
On Tue, Jun 18, 2019 at 02:32:15AM +0200, Armin Zentai wrote:
> After, I've done some tests, I confirmed, you were right.
>
> I was able to reproduce the issue with a very simple example code
> - create a few hundred folders within a folder
> - using the example code with a smaller BUF_SIZE, like 256, http://man7.org/linux/man-pages/man2/getdents.2.html
> - also deleting one folder in every iteration of the outer for loop
>
> This clearly reproduces the issue and the fuse lib's EINVAL is a false-positive error and it should return a simple empty array with fuse.OK return code.
OK, thanks for following up.
--b.
>
>
> Thanks,
> Armin
>
> > On 2019. Jun 4., at 17:12, J. Bruce Fields <bfields@fieldses.org> wrote:
> >
> > On Tue, Jun 04, 2019 at 12:51:11PM +0200, Armin Zentai wrote:
> >> Hi everyone,
> >>
> >>
> >> I'm developing a fuse software and it should be able to run _under_ an nfsd export.
> >> Currently I've stripped everything out from the fuse software, and only using it as a mirrorfs. It's written in go and using this lib: https://github.com/hanwen/go-fuse.
> >>
> >> My issue a bit complex, but I'll try to explain it as detailed as I can. I like to get some guidance or hint how to proceed with the debugging or a solution of course.
> >>
> >>
> >> NFS and kernel settings:
> >> client+server: Debian 9.0 / kernel-5.2.0 (I compiled it with debug symbols)
> >> export options: (rw,sync,no_subtree_check,all_squash,anonuid=505,anongid=20,fsid=4193281846142082570)
> >> client mount options: type nfs4 (rw,noatime,vers=4.2,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,timeo=600,retrans=6,sec=sys,clientaddr=10.135.105.205,local_lock=none,addr=10.135.101.174,_netdev)
> >>
> >> NFSv3 is explicitly disabled on the server:
> >> cat /proc/fs/nfsd/versions
> >> -2 -3 +4 +4.1 +4.2
> >>
> >>
> >>
> >> The error itself is non-deterministic, but reproducible within ~10 minutes.
> >>
> >> Sometimes the client is calling one more READDIR after an empty READDIR reply. The extra READDIR is called with an increased cookie value.
> >
> > I don't know why the client's doing that, it does sound a little weird.
> > I guess the higher cookie value is something cached from a previous
> > READDIR of the directory. (I think you said it was removing files so
> > it's not surprising that a cached cookie might point to a position in
> > the directory that's no longer there.) But I don't know why it would be
> > issuing another READDIR after the client already set the EOF bit on a
> > previous one.
> >
> > Off the top of my head that client behavior sounds weird and suboptimal,
> > but also harmless.
> >
> >> This behaviour is causing an array out-of-bound read in the fuse lib.
> >>
> >> This results in an EINVAL error in the go fuse library.
> >> https://github.com/hanwen/go-fuse/blob/master/fuse/nodefs/dir.go#L42
> >> https://github.com/hanwen/go-fuse/blob/master/fuse/nodefs/dir.go#L72
> >> (also there is an open issue by me, https://github.com/hanwen/go-fuse/issues/297)
> >
> > I think that's incorrect.
> >
> > Assuming the client is using a cookie value that was previously handed
> > out by the server at some point in the past, the server still needs to
> > honor that cookie. So it should probably just be returning a succesful
> > READDIR with zero entries.
> >
> > --b.
> >
> >
> >>
> >> If this behaviour is totally accepted, then this EINVAL return value can be replaced with fuse.OK in the lib, but I'm a bit curious what is causing this.
> >>
> >>
> >>
> >> The easiest way to reproduce it is using an npm install (without an existing node_modules folder) and in the end it may produce the error.
> >> I haven't debugged the npm install process or reproduced it with a simpler code, but it's happening when removing a directory structure with files.
> >> The npm install at the end removes the fsevents folder with its files. It is downloaded, but not supported on linux (only on OSX) and it removes the module.
> >> So probably it's connected with some npm behaviour which is trying to remove multiple files with multiple async file delete calls.
> >> rm -rf itself can't reproduce the issue.
> >>
> >> If I'm running npm install && rm -rf node_modules in a loop, I can reproduce the error in every 2nd - 10th run (approx 2 - 15 minutes).
> >>
> >>
> >>
> >> I've found these things while debugging:
> >>
> >> The client is always using readdirplus functions to get directory entries.
> >> If I get a plus=false, then it indicates an error.
> >> Although the error can happen without plus=false too (approx 50/50 chance).
> >>
> >>
> >> I've used this bpftrace to get it.
> >>
> >> ```
> >> kprobe:nfs4_xdr_enc_readdir {
> >> $a = ((struct nfs4_readdir_arg *)arg2);
> >> if ($a->plus != 1) {
> >> time("%H:%M:%S\n");
> >> printf("nfs4_xdr_enc_readdir count=%u plus=%u cookie=%llu\n",
> >> $a->count, $a->plus, $a->cookie);
> >> }
> >> }
> >> ```
> >>
> >> Also there is a kstack, from nfs4_xdr_enc_readdir:
> >>
> >> nfs4_xdr_enc_readdir count=262144 plus=0 cookie=24
> >> nfs4_xdr_enc_readdir kstack
> >>
> >> nfs4_xdr_enc_readdir+1
> >> rpcauth_wrap_req_encode+35
> >> call_encode+357
> >> __rpc_execute+137
> >> rpc_run_task+268
> >> nfs4_call_sync_sequence+100
> >> _nfs4_proc_readdir+277
> >> nfs4_proc_readdir+141
> >> nfs_readdir_xdr_to_array+375
> >> nfs_readdir+613
> >> iterate_dir+320
> >> __x64_sys_getdents+169
> >> do_syscall_64+85
> >> entry_SYSCALL_64_after_hwframe+68
> >>
> >>
> >> Also I found out the extra READDIR call, always (mostly?) has an increased (duplicated) dircount parameter.
> >>
> >>
> >>> From wireshark dump there is an example:
> >>
> >> Packets from 1 to 4 are totally normal communication.
> >> 5-6 are the extra ones.
> >> In packet 3, the dircount is 65536 and in packet 5 it is 131072.
> >>
> >>
> >> 1. client -> server
> >> Remote Procedure Call, Type:Call XID:0x04a37c12
> >> Network File System, Ops(3): SEQUENCE, PUTFH, READDIR
> >> [Program Version: 4]
> >> [V4 Procedure: COMPOUND (1)]
> >> Tag: <EMPTY>
> >> minorversion: 2
> >> Operations (count: 3): SEQUENCE, PUTFH, READDIR
> >> Opcode: SEQUENCE (53)
> >> sessionid: a2fdea5cc954b1470300000000000000
> >> seqid: 0x0001e92f
> >> slot id: 25
> >> high slot id: 25
> >> cache this?: No
> >> Opcode: PUTFH (22)
> >> FileHandle
> >> Opcode: READDIR (26)
> >> cookie: 0
> >> cookie_verf: 0
> >> dircount: 65514
> >> maxcount: 262056
> >> Attr mask[0]: 0x0018091a (Type, Change, Size, FSID, RDAttr_Error, Filehandle, FileId)
> >> Attr mask[1]: 0x00b0a23a (Mode, NumLinks, Owner, Owner_Group, RawDev, Space_Used, Time_Access, Time_Metadata, Time_Modify, Mounted_on_FileId)
> >> [Main Opcode: READDIR (26)]
> >>
> >> 2. server -> client
> >> Network File System, Ops(3): SEQUENCE PUTFH READDIR
> >> [Program Version: 4]
> >> [V4 Procedure: COMPOUND (1)]
> >> Status: NFS4_OK (0)
> >> Tag: <EMPTY>
> >> Operations (count: 3)
> >> Opcode: SEQUENCE (53)
> >> Status: NFS4_OK (0)
> >> sessionid: a2fdea5cc954b1470300000000000000
> >> seqid: 0x0001e92f
> >> slot id: 25
> >> high slot id: 29
> >> target high slot id: 29
> >> status flags: 0x00000000
> >> Opcode: PUTFH (22)
> >> Status: NFS4_OK (0)
> >> Opcode: READDIR (26)
> >> Status: NFS4_OK (0)
> >> verifier: 0x0000000000000000
> >> Directory Listing
> >> Entry: node-pre-gyp
> >> Entry: needle
> >> Entry: iconv-lite
> >> Entry: readable-stream
> >> Value Follows: No
> >> EOF: Yes
> >> [Main Opcode: READDIR (26)]
> >>
> >> 3. client -> server
> >> Remote Procedure Call, Type:Call XID:0x16a37c12
> >> Network File System, Ops(3): SEQUENCE, PUTFH, READDIR
> >> [Program Version: 4]
> >> [V4 Procedure: COMPOUND (1)]
> >> Tag: <EMPTY>
> >> minorversion: 2
> >> Operations (count: 3): SEQUENCE, PUTFH, READDIR
> >> Opcode: SEQUENCE (53)
> >> sessionid: a2fdea5cc954b1470300000000000000
> >> seqid: 0x000cd063
> >> slot id: 15
> >> high slot id: 24
> >> cache this?: No
> >> Opcode: PUTFH (22)
> >> FileHandle
> >> Opcode: READDIR (26)
> >> cookie: 6
> >> cookie_verf: 0
> >> dircount: 65536
> >> maxcount: 262144
> >> Attr mask[0]: 0x0018091a (Type, Change, Size, FSID, RDAttr_Error, Filehandle, FileId)
> >> Attr mask[1]: 0x00b0a23a (Mode, NumLinks, Owner, Owner_Group, RawDev, Space_Used, Time_Access, Time_Metadata, Time_Modify, Mounted_on_FileId)
> >> [Main Opcode: READDIR (26)]
> >>
> >> 4. server -> client
> >> Remote Procedure Call, Type:Reply XID:0x16a37c12
> >> Network File System, Ops(3): SEQUENCE PUTFH READDIR
> >> [Program Version: 4]
> >> [V4 Procedure: COMPOUND (1)]
> >> Status: NFS4_OK (0)
> >> Tag: <EMPTY>
> >> Operations (count: 3)
> >> Opcode: SEQUENCE (53)
> >> Status: NFS4_OK (0)
> >> sessionid: a2fdea5cc954b1470300000000000000
> >> seqid: 0x000cd063
> >> slot id: 15
> >> high slot id: 29
> >> target high slot id: 29
> >> status flags: 0x00000000
> >> Opcode: PUTFH (22)
> >> Status: NFS4_OK (0)
> >> Opcode: READDIR (26)
> >> Status: NFS4_OK (0)
> >> verifier: 0x0000000000000000
> >> Directory Listing
> >> Value Follows: No
> >> EOF: Yes
> >> [Main Opcode: READDIR (26)]
> >>
> >> 5. client -> server
> >> Remote Procedure Call, Type:Call XID:0x32a37c12
> >> Network File System, Ops(3): SEQUENCE, PUTFH, READDIR
> >> [Program Version: 4]
> >> [V4 Procedure: COMPOUND (1)]
> >> Tag: <EMPTY>
> >> minorversion: 2
> >> Operations (count: 3): SEQUENCE, PUTFH, READDIR
> >> Opcode: SEQUENCE (53)
> >> sessionid: a2fdea5cc954b1470300000000000000
> >> seqid: 0x0001585c
> >> slot id: 26
> >> high slot id: 26
> >> cache this?: No
> >> Opcode: PUTFH (22)
> >> FileHandle
> >> Opcode: READDIR (26)
> >> cookie: 7
> >> cookie_verf: 0
> >> dircount: 131072
> >> maxcount: 262144
> >> Attr mask[0]: 0x00000800 (RDAttr_Error)
> >> Attr mask[1]: 0x00800000 (Mounted_on_FileId)
> >> [Main Opcode: READDIR (26)]
> >>
> >> 6. server -> client
> >> Remote Procedure Call, Type:Reply XID:0x32a37c12
> >> Network File System, Ops(3): SEQUENCE PUTFH READDIR(NFS4ERR_INVAL)
> >> [Program Version: 4]
> >> [V4 Procedure: COMPOUND (1)]
> >> Status: NFS4ERR_INVAL (22)
> >> Tag: <EMPTY>
> >> Operations (count: 3)
> >> Opcode: SEQUENCE (53)
> >> Status: NFS4_OK (0)
> >> sessionid: a2fdea5cc954b1470300000000000000
> >> seqid: 0x0001585c
> >> slot id: 26
> >> high slot id: 29
> >> target high slot id: 29
> >> status flags: 0x00000000
> >> Opcode: PUTFH (22)
> >> Status: NFS4_OK (0)
> >> Opcode: READDIR (26)
> >> Status: NFS4ERR_INVAL (22)
> >> [Main Opcode: READDIR (26)]
> >>
> >>
> >> Thanks,
> >> Armin
^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2019-06-18 17:58 UTC | newest]
Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2019-06-04 10:51 Bug? nfs export on fuse, one more READDIR call after a finished directory read Armin Zentai
2019-06-04 15:12 ` J. Bruce Fields
2019-06-18 0:32 ` Armin Zentai
2019-06-18 17:58 ` J. Bruce Fields
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).