2020-01-22 09:46:02

by Felix Rubio

[permalink] [raw]
Subject: kerberized NFSv4 client reporting operation not permitted when mounting with sec=sys

Hi everybody,

I have a kerberized NFSv4 server that is exporting a mountpoint:

/home 10.0.0.0/8(rw,no_subtree_check,sec=krb5:krb5i:krb5p)

if I mount that export with this command on the client, it works as
expected:

/sbin/mount.nfs4 NFS.domain:/home /network/home -o
_netdev,noatime,hard,sec=krb5

However, if I modify the export to be

/home 10.0.0.0/8(rw,no_subtree_check,sec=sys:krb5:krb5i:krb5p)

and I mount that export with sec=sys, as

/sbin/mount.nfs4 NFS.domain:/home /network/home -o
_netdev,noatime,hard,sec=sys

I get the following error:

mount.nfs4: timeout set for Fri Jan 17 14:11:32 2020
mount.nfs4: trying text-based options
'hard,sec=sys,vers=4.1,addr=10.2.2.9,clientaddr=10.2.0.12'
mount.nfs4: mount(2): Operation not permitted
mount.nfs4: Operation not permitted

What might be the reason for this behavior?

--
Felix Rubio
"Don't believe what you're told. Double check."


2020-01-22 18:31:04

by Benjamin Coddington

[permalink] [raw]
Subject: Re: kerberized NFSv4 client reporting operation not permitted when mounting with sec=sys

On 22 Jan 2020, at 4:22, Felix Rubio wrote:

> Hi everybody,
>
> I have a kerberized NFSv4 server that is exporting a mountpoint:
>
> /home 10.0.0.0/8(rw,no_subtree_check,sec=krb5:krb5i:krb5p)
>
> if I mount that export with this command on the client, it works as
> expected:
>
> /sbin/mount.nfs4 NFS.domain:/home /network/home -o
> _netdev,noatime,hard,sec=krb5
>
> However, if I modify the export to be
>
> /home 10.0.0.0/8(rw,no_subtree_check,sec=sys:krb5:krb5i:krb5p)
>
> and I mount that export with sec=sys, as
>
> /sbin/mount.nfs4 NFS.domain:/home /network/home -o
> _netdev,noatime,hard,sec=sys
>
> I get the following error:
>
> mount.nfs4: timeout set for Fri Jan 17 14:11:32 2020
> mount.nfs4: trying text-based options
> 'hard,sec=sys,vers=4.1,addr=10.2.2.9,clientaddr=10.2.0.12'
> mount.nfs4: mount(2): Operation not permitted
> mount.nfs4: Operation not permitted
>
> What might be the reason for this behavior?

Hi Felix,

I don't know. Can you get more information? Try again after `rpcdebug
-m
nfs -s mount`. That will turn up debugging for messages labeled for
mount,
and the output will be in the kernel log. There are other facilities
there,
see rpcdebug(8).

Another good option is getting a network capture of the mount attempt
and
trying to figure out if the server is returning an error, or the client
is
generating the error.

There are also a lot of "nfs", "nfs4", and "rpc" tracepoints you can
enable
to get more information.

Ben

2020-01-23 09:05:49

by Felix Rubio

[permalink] [raw]
Subject: Re: kerberized NFSv4 client reporting operation not permitted when mounting with sec=sys

Hi Ben,

Thank your for trying to help. Indeed, I can get as much information
as you might need (I am the administrator of those machines). After
enabling rpcdebug -m nfs -s mount on the client this is what I get:

[ 461.238568] NFS: nfs mount
opts='hard,sec=sys,vers=4.1,addr=10.0.2.9,clientaddr=10.1.0.12'
[ 461.243621] NFS: parsing nfs mount option 'hard'
[ 461.246573] NFS: parsing nfs mount option 'sec=sys'
[ 461.249809] NFS: parsing sec=sys option
[ 461.252364] NFS: parsing nfs mount option 'vers=4.1'
[ 461.255472] NFS: parsing nfs mount option 'addr=10.0.2.9'
[ 461.258864] NFS: parsing nfs mount option
'clientaddr=10.1.0.12'
[ 461.262610] NFS: MNTPATH: '/home'
[ 461.264757] --> nfs4_try_mount()
[ 461.273063] <-- nfs4_try_mount() = -1 [error]

when running tcpdump on the nfs server (tcpdump -i eth0 host 10.1.0.12
and port nfs -n -s 0 -vvv), and mounting on the client, this is what I
get:

tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture
size 262144 bytes
09:55:01.603947 IP (tos 0x0, ttl 64, id 15242, offset 0, flags [DF],
proto TCP (6), length 188)
10.1.0.12.epp > 10.0.2.9.nfs: Flags [P.], cksum 0x1fdf
(correct), seq 1347340908:1347341056, ack 1722815553, win 1919, length
148: NFS request xid 3760933574 144 getattr fh 0,1/53
09:55:01.604325 IP (tos 0x0, ttl 64, id 38336, offset 0, flags [DF],
proto TCP (6), length 132)
10.0.2.9.nfs > 10.1.0.12.epp: Flags [P.], cksum 0x168c
(incorrect -> 0x08f4), seq 1:93, ack 148, win 1432, length 92: NFS reply
xid 3760933574 reply ok 88 getattr ERROR: unk 10016
09:55:01.604717 IP (tos 0x0, ttl 64, id 15243, offset 0, flags [DF],
proto TCP (6), length 40)
10.1.0.12.epp > 10.0.2.9.nfs: Flags [.], cksum 0xf0e6 (correct),
seq 148, ack 93, win 1919, length 0
09:55:01.612334 IP (tos 0x0, ttl 64, id 15244, offset 0, flags [DF],
proto TCP (6), length 252)
10.1.0.12.epp > 10.0.2.9.nfs: Flags [P.], cksum 0xe9ed
(correct), seq 148:360, ack 93, win 1919, length 212: NFS request xid
3777710790 208 getattr fh 0,1/53
09:55:01.612495 IP (tos 0x0, ttl 64, id 38337, offset 0, flags [DF],
proto TCP (6), length 240)
10.0.2.9.nfs > 10.1.0.12.epp: Flags [P.], cksum 0x16f8
(incorrect -> 0x417f), seq 93:293, ack 360, win 1432, length 200: NFS
reply xid 3777710790 reply ok 196 getattr NON 4 ids 0/47982174 sz
-1769090185
09:55:01.652270 IP (tos 0x0, ttl 64, id 15245, offset 0, flags [DF],
proto TCP (6), length 40)
10.1.0.12.epp > 10.0.2.9.nfs: Flags [.], cksum 0xef34 (correct),
seq 360, ack 293, win 1941, length 0

I have noticed there is this error 10016, that in nfs4.h translates to
NFS4ERR_WRONGSEC, suggesting that the server does not allow 'sys', but I
have checked again my /etc/exports file and contains

/home 10.0.0.0/8(rw,no_subtree_check,sec=sys:krb5:krb5i:krb5p)

and also is reported by the operating system:

# cat /proc/fs/nfsd/exports
/export/home
10.0.0.0/8(rw,root_squash,sync,wdelay,no_subtree_check,uuid=0743ce63:00c1185a:00000000:00000000,sec=1:390003:390004:390005)

Any ideas?

Thank you!
Felix


---
Felix Rubio
"Don't believe what you're told. Double check."

On 2020-01-22 19:30, Benjamin Coddington wrote:
> On 22 Jan 2020, at 4:22, Felix Rubio wrote:
>
>> Hi everybody,
>>
>> I have a kerberized NFSv4 server that is exporting a mountpoint:
>>
>> /home 10.0.0.0/8(rw,no_subtree_check,sec=krb5:krb5i:krb5p)
>>
>> if I mount that export with this command on the client, it works as
>> expected:
>>
>> /sbin/mount.nfs4 NFS.domain:/home /network/home -o
>> _netdev,noatime,hard,sec=krb5
>>
>> However, if I modify the export to be
>>
>> /home 10.0.0.0/8(rw,no_subtree_check,sec=sys:krb5:krb5i:krb5p)
>>
>> and I mount that export with sec=sys, as
>>
>> /sbin/mount.nfs4 NFS.domain:/home /network/home -o
>> _netdev,noatime,hard,sec=sys
>>
>> I get the following error:
>>
>> mount.nfs4: timeout set for Fri Jan 17 14:11:32 2020
>> mount.nfs4: trying text-based options
>> 'hard,sec=sys,vers=4.1,addr=10.2.2.9,clientaddr=10.2.0.12'
>> mount.nfs4: mount(2): Operation not permitted
>> mount.nfs4: Operation not permitted
>>
>> What might be the reason for this behavior?
>
> Hi Felix,
>
> I don't know. Can you get more information? Try again after `rpcdebug
> -m
> nfs -s mount`. That will turn up debugging for messages labeled for
> mount,
> and the output will be in the kernel log. There are other facilities
> there,
> see rpcdebug(8).
>
> Another good option is getting a network capture of the mount attempt
> and
> trying to figure out if the server is returning an error, or the client
> is
> generating the error.
>
> There are also a lot of "nfs", "nfs4", and "rpc" tracepoints you can
> enable
> to get more information.
>
> Ben

2020-01-24 15:11:47

by Benjamin Coddington

[permalink] [raw]
Subject: Re: kerberized NFSv4 client reporting operation not permitted when mounting with sec=sys

Hi Felix - now see if you can turn up the nfsd debug messages on the
server
during that mount. It does seem odd. Its also hard to see from your
capture what security the client is trying to use for that GETATTR. You
can
use `tshark -r/path/to/pcap` to get a nicer summary, then `tshark -V
-r/path/to/pcap frame.number==<frame of interest> to get very verbose
results..

Ben

On 23 Jan 2020, at 4:03, Felix Rubio wrote:

> Hi Ben,
>
> Thank your for trying to help. Indeed, I can get as much
> information as you might need (I am the administrator of those
> machines). After enabling rpcdebug -m nfs -s mount on the client this
> is what I get:
>
> [ 461.238568] NFS: nfs mount
> opts='hard,sec=sys,vers=4.1,addr=10.0.2.9,clientaddr=10.1.0.12'
> [ 461.243621] NFS: parsing nfs mount option 'hard'
> [ 461.246573] NFS: parsing nfs mount option 'sec=sys'
> [ 461.249809] NFS: parsing sec=sys option
> [ 461.252364] NFS: parsing nfs mount option 'vers=4.1'
> [ 461.255472] NFS: parsing nfs mount option 'addr=10.0.2.9'
> [ 461.258864] NFS: parsing nfs mount option
> 'clientaddr=10.1.0.12'
> [ 461.262610] NFS: MNTPATH: '/home'
> [ 461.264757] --> nfs4_try_mount()
> [ 461.273063] <-- nfs4_try_mount() = -1 [error]
>
> when running tcpdump on the nfs server (tcpdump -i eth0 host 10.1.0.12
> and port nfs -n -s 0 -vvv), and mounting on the client, this is what I
> get:
>
> tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture
> size 262144 bytes
> 09:55:01.603947 IP (tos 0x0, ttl 64, id 15242, offset 0, flags
> [DF], proto TCP (6), length 188)
> 10.1.0.12.epp > 10.0.2.9.nfs: Flags [P.], cksum 0x1fdf
> (correct), seq 1347340908:1347341056, ack 1722815553, win 1919, length
> 148: NFS request xid 3760933574 144 getattr fh 0,1/53
> 09:55:01.604325 IP (tos 0x0, ttl 64, id 38336, offset 0, flags
> [DF], proto TCP (6), length 132)
> 10.0.2.9.nfs > 10.1.0.12.epp: Flags [P.], cksum 0x168c
> (incorrect -> 0x08f4), seq 1:93, ack 148, win 1432, length 92: NFS
> reply xid 3760933574 reply ok 88 getattr ERROR: unk 10016
> 09:55:01.604717 IP (tos 0x0, ttl 64, id 15243, offset 0, flags
> [DF], proto TCP (6), length 40)
> 10.1.0.12.epp > 10.0.2.9.nfs: Flags [.], cksum 0xf0e6
> (correct), seq 148, ack 93, win 1919, length 0
> 09:55:01.612334 IP (tos 0x0, ttl 64, id 15244, offset 0, flags
> [DF], proto TCP (6), length 252)
> 10.1.0.12.epp > 10.0.2.9.nfs: Flags [P.], cksum 0xe9ed
> (correct), seq 148:360, ack 93, win 1919, length 212: NFS request xid
> 3777710790 208 getattr fh 0,1/53
> 09:55:01.612495 IP (tos 0x0, ttl 64, id 38337, offset 0, flags
> [DF], proto TCP (6), length 240)
> 10.0.2.9.nfs > 10.1.0.12.epp: Flags [P.], cksum 0x16f8
> (incorrect -> 0x417f), seq 93:293, ack 360, win 1432, length 200: NFS
> reply xid 3777710790 reply ok 196 getattr NON 4 ids 0/47982174 sz
> -1769090185
> 09:55:01.652270 IP (tos 0x0, ttl 64, id 15245, offset 0, flags
> [DF], proto TCP (6), length 40)
> 10.1.0.12.epp > 10.0.2.9.nfs: Flags [.], cksum 0xef34
> (correct), seq 360, ack 293, win 1941, length 0
>
> I have noticed there is this error 10016, that in nfs4.h translates to
> NFS4ERR_WRONGSEC, suggesting that the server does not allow 'sys', but
> I have checked again my /etc/exports file and contains
>
> /home 10.0.0.0/8(rw,no_subtree_check,sec=sys:krb5:krb5i:krb5p)
>
> and also is reported by the operating system:
>
> # cat /proc/fs/nfsd/exports
> /export/home
> 10.0.0.0/8(rw,root_squash,sync,wdelay,no_subtree_check,uuid=0743ce63:00c1185a:00000000:00000000,sec=1:390003:390004:390005)
>
> Any ideas?
>
> Thank you!
> Felix
>
>
> ---
> Felix Rubio
> "Don't believe what you're told. Double check."
>
> On 2020-01-22 19:30, Benjamin Coddington wrote:
>> On 22 Jan 2020, at 4:22, Felix Rubio wrote:
>>
>>> Hi everybody,
>>>
>>> I have a kerberized NFSv4 server that is exporting a mountpoint:
>>>
>>> /home 10.0.0.0/8(rw,no_subtree_check,sec=krb5:krb5i:krb5p)
>>>
>>> if I mount that export with this command on the client, it works as
>>> expected:
>>>
>>> /sbin/mount.nfs4 NFS.domain:/home /network/home -o
>>> _netdev,noatime,hard,sec=krb5
>>>
>>> However, if I modify the export to be
>>>
>>> /home 10.0.0.0/8(rw,no_subtree_check,sec=sys:krb5:krb5i:krb5p)
>>>
>>> and I mount that export with sec=sys, as
>>>
>>> /sbin/mount.nfs4 NFS.domain:/home /network/home -o
>>> _netdev,noatime,hard,sec=sys
>>>
>>> I get the following error:
>>>
>>> mount.nfs4: timeout set for Fri Jan 17 14:11:32 2020
>>> mount.nfs4: trying text-based options
>>> 'hard,sec=sys,vers=4.1,addr=10.2.2.9,clientaddr=10.2.0.12'
>>> mount.nfs4: mount(2): Operation not permitted
>>> mount.nfs4: Operation not permitted
>>>
>>> What might be the reason for this behavior?
>>
>> Hi Felix,
>>
>> I don't know. Can you get more information? Try again after
>> `rpcdebug -m
>> nfs -s mount`. That will turn up debugging for messages labeled for
>> mount,
>> and the output will be in the kernel log. There are other facilities
>> there,
>> see rpcdebug(8).
>>
>> Another good option is getting a network capture of the mount attempt
>> and
>> trying to figure out if the server is returning an error, or the
>> client is
>> generating the error.
>>
>> There are also a lot of "nfs", "nfs4", and "rpc" tracepoints you can
>> enable
>> to get more information.
>>
>> Ben

2020-01-24 20:55:57

by Felix Rubio

[permalink] [raw]
Subject: Re: kerberized NFSv4 client reporting operation not permitted when mounting with sec=sys

Hi Benjamin,

I have enabled the debug logging on nfsd by running

When mounting from the client, this is what I get:

[629588.647849] nfsd_dispatch: vers 4 proc 1
[629588.655615] nfsv4 compound op #1/1: 53 (OP_SEQUENCE)
[629588.663926] __find_in_sessionid_hashtbl: 1579604994:2010353049:95:0
[629588.675361] nfsd4_sequence: slotid 0
[629588.679065] check_slot_seqid enter. seqid 644 slot_seqid 643
[629588.684589] nfsv4 compound op ffff882839705080 opcnt 1 #1: 53:
status 0
[629588.691545] nfsv4 compound returned 0
[629588.695292] --> nfsd4_store_cache_entry slot ffff882806e83000
[629588.701933] renewing client (clientid 5e26dc02/77d38d99)
[629591.804857] nfsd_dispatch: vers 4 proc 1
[629591.809364] nfsv4 compound op #1/4: 53 (OP_SEQUENCE)
[629591.814944] __find_in_sessionid_hashtbl: 1579604994:2010353053:99:0
[629591.822163] nfsd4_sequence: slotid 0
[629591.826670] check_slot_seqid enter. seqid 155 slot_seqid 154
[629591.832771] nfsv4 compound op ffff882839705080 opcnt 4 #1: 53:
status 0
[629591.839864] nfsv4 compound op #2/4: 24 (OP_PUTROOTFH)
[629591.845161] nfsd: fh_compose(exp 08:02/17468677 /export,
ino=17468677)
[629591.851706] nfsv4 compound op ffff882839705080 opcnt 4 #2: 24:
status 10016
[629591.859660] nfsv4 compound returned 10016
[629591.864797] --> nfsd4_store_cache_entry slot ffff882838b9e000
[629591.872968] renewing client (clientid 5e26dc02/77d38d9d)
[629591.889085] nfsd_dispatch: vers 4 proc 1
[629591.893713] nfsv4 compound op #1/4: 53 (OP_SEQUENCE)
[629591.899703] __find_in_sessionid_hashtbl: 1579604994:2010353053:99:0
[629591.906687] nfsd4_sequence: slotid 0
[629591.912695] check_slot_seqid enter. seqid 156 slot_seqid 155
[629591.918261] nfsv4 compound op ffff882839705080 opcnt 4 #1: 53:
status 0
[629591.924866] nfsv4 compound op #2/4: 22 (OP_PUTFH)
[629591.931075] nfsd: fh_verify(32: 01060001 63ce4307 5a18c100 00000000
00000000 1fba000a)
[629591.940556] nfsv4 compound op ffff882839705080 opcnt 4 #2: 22:
status 0
[629591.948776] nfsv4 compound op #3/4: 3 (OP_ACCESS)
[629591.954607] nfsd: fh_verify(32: 01060001 63ce4307 5a18c100 00000000
00000000 1fba000a)
[629591.967117] nfsv4 compound op ffff882839705080 opcnt 4 #3: 3: status
0
[629591.975364] nfsv4 compound op #4/4: 9 (OP_GETATTR)
[629591.980854] nfsd: fh_verify(32: 01060001 63ce4307 5a18c100 00000000
00000000 1fba000a)
[629591.990257] nfsv4 compound op ffff882839705080 opcnt 4 #4: 9: status
0
[629591.996796] nfsv4 compound returned 0
[629592.001758] --> nfsd4_store_cache_entry slot ffff882838b9e000
[629592.008061] renewing client (clientid 5e26dc02/77d38d9d)

Using wireshark, this is the log of the packages from/to that ip
address:

# tshark -i eth0 -p -w /tmp/nfs_mount.cap host 10.1.0.12 and port nfs
# tshark -r /tmp/nfs_mount.cap
1 0.000000000 10.1.0.12 -> 10.0.2.9 NFS 202 V4 Call PUTROOTFH |
GETATTR
2 0.000058001 10.0.2.9 -> 10.1.0.12 TCP 54 nfs > rndc [ACK]
Seq=1 Ack=149 Win=1432 Len=0
3 0.074041118 10.0.2.9 -> 10.1.0.12 NFS 146 V4 Reply (Call In
1) PUTROOTFH Status: NFS4ERR_WRONGSEC
4 0.074927630 10.1.0.12 -> 10.0.2.9 TCP 54 rndc > nfs [ACK]
Seq=149 Ack=93 Win=1476 Len=0
5 0.084223658 10.1.0.12 -> 10.0.2.9 NFS 266 V4 Call ACCESS FH:
0xea1b01ae, [Check: RD LU MD XT DL]
6 0.084270458 10.0.2.9 -> 10.1.0.12 TCP 54 nfs > rndc [ACK]
Seq=93 Ack=361 Win=1432 Len=0
7 0.208635667 10.0.2.9 -> 10.1.0.12 NFS 254 V4 Reply (Call In
5) ACCESS, [Access Denied: RD MD XT DL], [Allowed: LU]
8 0.248855020 10.1.0.12 -> 10.0.2.9 TCP 54 rndc > nfs [ACK]
Seq=361 Ack=293 Win=1498 Len=0

I think the frame of interest is #1, so this is its contents:
Frame 1: 202 bytes on wire (1616 bits), 202 bytes captured (1616 bits)
on interface 0
Interface id: 0
Encapsulation type: Ethernet (1)
Arrival Time: Jan 24, 2020 17:39:05.721360043 CET
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1579883945.721360043 seconds
[Time delta from previous captured frame: 0.000000000 seconds]
[Time delta from previous displayed frame: 0.000000000 seconds]
[Time since reference or first frame: 0.000000000 seconds]
Frame Number: 1
Frame Length: 202 bytes (1616 bits)
Capture Length: 202 bytes (1616 bits)
[Frame is marked: False]
[Frame is ignored: False]
[Protocols in frame: eth:ip:tcp:rpc]
Ethernet II, Src: 00:81:c4:c1:50:7f (00:81:c4:c1:50:7f), Dst:
Microsof_44:24:d3 (00:0d:3a:44:24:d3)
Destination: Microsof_44:24:d3 (00:0d:3a:44:24:d3)
Address: Microsof_44:24:d3 (00:0d:3a:44:24:d3)
.... ..0. .... .... .... .... = LG bit: Globally unique address
(factory default)
.... ...0 .... .... .... .... = IG bit: Individual address
(unicast)
Source: 00:81:c4:c1:50:7f (00:81:c4:c1:50:7f)
Address: 00:81:c4:c1:50:7f (00:81:c4:c1:50:7f)
.... ..0. .... .... .... .... = LG bit: Globally unique address
(factory default)
.... ...0 .... .... .... .... = IG bit: Individual address
(unicast)
Type: IP (0x0800)
Internet Protocol Version 4, Src: 10.1.0.12 (10.1.0.12), Dst: 10.0.2.9
(10.0.2.9)
Version: 4
Header length: 20 bytes
Differentiated Services Field: 0x00 (DSCP 0x00: Default; ECN: 0x00:
Not-ECT (Not ECN-Capable Transport))
0000 00.. = Differentiated Services Codepoint: Default (0x00)
.... ..00 = Explicit Congestion Notification: Not-ECT (Not
ECN-Capable Transport) (0x00)
Total Length: 188
Identification: 0xa3e0 (41952)
Flags: 0x02 (Don't Fragment)
0... .... = Reserved bit: Not set
.1.. .... = Don't fragment: Set
..0. .... = More fragments: Not set
Fragment offset: 0
Time to live: 64
Protocol: TCP (6)
Header checksum: 0x8046 [validation disabled]
[Good: False]
[Bad: False]
Source: 10.1.0.12 (10.1.0.12)
Destination: 10.0.2.9 (10.0.2.9)
Transmission Control Protocol, Src Port: rndc (953), Dst Port: nfs
(2049), Seq: 1, Ack: 1, Len: 148
Source port: rndc (953)
Destination port: nfs (2049)
[Stream index: 0]
Sequence number: 1 (relative sequence number)
[Next sequence number: 149 (relative sequence number)]
Acknowledgment number: 1 (relative ack number)
Header length: 20 bytes
Flags: 0x018 (PSH, ACK)
000. .... .... = Reserved: Not set
...0 .... .... = Nonce: Not set
.... 0... .... = Congestion Window Reduced (CWR): Not set
.... .0.. .... = ECN-Echo: Not set
.... ..0. .... = Urgent: Not set
.... ...1 .... = Acknowledgment: Set
.... .... 1... = Push: Set
.... .... .0.. = Reset: Not set
.... .... ..0. = Syn: Not set
.... .... ...0 = Fin: Not set
Window size value: 1476
[Calculated window size: 1476]
[Window size scaling factor: -1 (unknown)]
Checksum: 0x4455 [validation disabled]
[Good Checksum: False]
[Bad Checksum: False]
[SEQ/ACK analysis]
[Bytes in flight: 148]
Remote Procedure Call, Type:Call XID:0xd17c6210
Fragment header: Last fragment, 144 bytes
1... .... .... .... .... .... .... .... = Last Fragment: Yes
.000 0000 0000 0000 0000 0000 1001 0000 = Fragment Length: 144
XID: 0xd17c6210 (3514589712)
Message Type: Call (0)
RPC Version: 2
Program: NFS (100003)
Program Version: 4
Procedure: COMPOUND (1)
Credentials
Flavor: AUTH_UNIX (1)
Length: 32
Stamp: 0x00418ae8
Machine Name: worker01
length: 8
contents: worker01
UID: 0
GID: 0
Auxiliary GIDs (1) [0]
GID: 0
Verifier
Flavor: AUTH_NULL (0)
Length: 0
Network File System, Ops(4): SEQUENCE, PUTROOTFH, GETFH, GETATTR
[Program Version: 4]
[V4 Procedure: COMPOUND (1)]
Tag: <EMPTY>
length: 0
contents: <EMPTY>
minorversion: 1
Operations (count: 4): SEQUENCE, PUTROOTFH, GETFH, GETATTR
Opcode: SEQUENCE (53)
sessionid: 02dc265e9d8dd3776300000000000000
seqid: 0x0000009b
slot id: 0
high slot id: 0
cache this?: No
Opcode: PUTROOTFH (24)
Opcode: GETFH (10)
Opcode: GETATTR (9)
Attr mask[0]: 0x0010011a (TYPE, CHANGE, SIZE, FSID, FILEID)
reqd_attr: TYPE (1)
reqd_attr: CHANGE (3)
reqd_attr: SIZE (4)
reqd_attr: FSID (8)
reco_attr: FILEID (20)
Attr mask[1]: 0x00b0a23a (MODE, NUMLINKS, OWNER,
OWNER_GROUP, RAWDEV, SPACE_USED, TIME_ACCESS, TIME_METADATA,
TIME_MODIFY, MOUNTED_ON_FILEID)
reco_attr: MODE (33)
reco_attr: NUMLINKS (35)
reco_attr: OWNER (36)
reco_attr: OWNER_GROUP (37)
reco_attr: RAWDEV (41)
reco_attr: SPACE_USED (45)
reco_attr: TIME_ACCESS (47)
reco_attr: TIME_METADATA (52)
reco_attr: TIME_MODIFY (53)
reco_attr: MOUNTED_ON_FILEID (55)
[Main Opcode: PUTROOTFH (24)]
[Main Opcode: GETATTR (9)]

Just in case, this is the answer of the server:
Frame 3: 146 bytes on wire (1168 bits), 146 bytes captured (1168 bits)
on interface 0
Interface id: 0
Encapsulation type: Ethernet (1)
Arrival Time: Jan 24, 2020 17:39:05.795401161 CET
[Time shift for this packet: 0.000000000 seconds]
Epoch Time: 1579883945.795401161 seconds
[Time delta from previous captured frame: 0.073983117 seconds]
[Time delta from previous displayed frame: 0.000000000 seconds]
[Time since reference or first frame: 0.074041118 seconds]
Frame Number: 3
Frame Length: 146 bytes (1168 bits)
Capture Length: 146 bytes (1168 bits)
[Frame is marked: False]
[Frame is ignored: False]
[Protocols in frame: eth:ip:tcp:rpc]
Ethernet II, Src: Microsof_44:24:d3 (00:0d:3a:44:24:d3), Dst:
12:34:56:78:9a:bc (12:34:56:78:9a:bc)
Destination: 12:34:56:78:9a:bc (12:34:56:78:9a:bc)
Address: 12:34:56:78:9a:bc (12:34:56:78:9a:bc)
.... ..1. .... .... .... .... = LG bit: Locally administered
address (this is NOT the factory default)
.... ...0 .... .... .... .... = IG bit: Individual address
(unicast)
Source: Microsof_44:24:d3 (00:0d:3a:44:24:d3)
Address: Microsof_44:24:d3 (00:0d:3a:44:24:d3)
.... ..0. .... .... .... .... = LG bit: Globally unique address
(factory default)
.... ...0 .... .... .... .... = IG bit: Individual address
(unicast)
Type: IP (0x0800)
Internet Protocol Version 4, Src: 10.0.2.9 (10.0.2.9), Dst: 10.1.0.12
(10.1.0.12)
Version: 4
Header length: 20 bytes
Differentiated Services Field: 0x00 (DSCP 0x00: Default; ECN: 0x00:
Not-ECT (Not ECN-Capable Transport))
0000 00.. = Differentiated Services Codepoint: Default (0x00)
.... ..00 = Explicit Congestion Notification: Not-ECT (Not
ECN-Capable Transport) (0x00)
Total Length: 132
Identification: 0x794c (31052)
Flags: 0x02 (Don't Fragment)
0... .... = Reserved bit: Not set
.1.. .... = Don't fragment: Set
..0. .... = More fragments: Not set
Fragment offset: 0
Time to live: 64
Protocol: TCP (6)
Header checksum: 0xab12 [validation disabled]
[Good: False]
[Bad: False]
Source: 10.0.2.9 (10.0.2.9)
Destination: 10.1.0.12 (10.1.0.12)
Transmission Control Protocol, Src Port: nfs (2049), Dst Port: rndc
(953), Seq: 1, Ack: 149, Len: 92
Source port: nfs (2049)
Destination port: rndc (953)
[Stream index: 0]
Sequence number: 1 (relative sequence number)
[Next sequence number: 93 (relative sequence number)]
Acknowledgment number: 149 (relative ack number)
Header length: 20 bytes
Flags: 0x018 (PSH, ACK)
000. .... .... = Reserved: Not set
...0 .... .... = Nonce: Not set
.... 0... .... = Congestion Window Reduced (CWR): Not set
.... .0.. .... = ECN-Echo: Not set
.... ..0. .... = Urgent: Not set
.... ...1 .... = Acknowledgment: Set
.... .... 1... = Push: Set
.... .... .0.. = Reset: Not set
.... .... ..0. = Syn: Not set
.... .... ...0 = Fin: Not set
Window size value: 1432
[Calculated window size: 1432]
[Window size scaling factor: -1 (unknown)]
Checksum: 0x168c [validation disabled]
[Good Checksum: False]
[Bad Checksum: False]
[SEQ/ACK analysis]
[Bytes in flight: 92]
Remote Procedure Call, Type:Reply XID:0xd17c6210
Fragment header: Last fragment, 88 bytes
1... .... .... .... .... .... .... .... = Last Fragment: Yes
.000 0000 0000 0000 0000 0000 0101 1000 = Fragment Length: 88
XID: 0xd17c6210 (3514589712)
Message Type: Reply (1)
[Program: NFS (100003)]
[Program Version: 4]
[Procedure: COMPOUND (1)]
Reply State: accepted (0)
[This is a reply to a request in frame 1]
[Time from request: 0.074041118 seconds]
Verifier
Flavor: AUTH_NULL (0)
Length: 0
Accept State: RPC executed successfully (0)
Network File System, Ops(2): SEQUENCE PUTROOTFH(NFS4ERR_WRONGSEC)
[Program Version: 4]
[V4 Procedure: COMPOUND (1)]
Status: NFS4ERR_WRONGSEC (10016)
Tag: <EMPTY>
length: 0
contents: <EMPTY>
Operations (count: 2)
Opcode: SEQUENCE (53)
Status: NFS4_OK (0)
sessionid: 02dc265e9d8dd3776300000000000000
seqid: 0x0000009b
slot id: 0
high slot id: 9
target high slot id: 9
status flags: 0x00000000
.... .... .... .... .... .... .... ...0 =
SEQ4_STATUS_CB_PATH_DOWN: Not set
.... .... .... .... .... .... .... ..0. =
SEQ4_STATUS_CB_GSS_CONTEXTS_EXPIRING: Not set
.... .... .... .... .... .... .... .0.. =
SEQ4_STATUS_CB_GSS_CONTEXTS_EXPIRED: Not set
.... .... .... .... .... .... .... 0... =
SEQ4_STATUS_EXPIRED_ALL_STATE_REVOKED: Not set
.... .... .... .... .... .... ...0 .... =
SEQ4_STATUS_EXPIRED_SOME_STATE_REVOKED: Not set
.... .... .... .... .... .... ..0. .... =
SEQ4_STATUS_ADMIN_STATE_REVOKED: Not set
.... .... .... .... .... .... .0.. .... =
SEQ4_STATUS_RECALLABLE_STATE_REVOKED: Not set
.... .... .... .... .... .... 0... .... =
SEQ4_STATUS_LEASE_MOVED: Not set
.... .... .... .... .... ...0 .... .... =
SEQ4_STATUS_RESTART_RECLAIM_NEEDED: Not set
.... .... .... .... .... ..0. .... .... =
SEQ4_STATUS_CB_PATH_DOWN_SESSION: Not set
.... .... .... .... .... .0.. .... .... =
SEQ4_STATUS_BACKCHANNEL_FAULT: Not set
.... .... .... .... .... 0... .... .... =
SEQ4_STATUS_DEVID_CHANGED: Not set
.... .... .... .... ...0 .... .... .... =
SEQ4_STATUS_DEVID_DELETED: Not set
Opcode: PUTROOTFH (24)
Status: NFS4ERR_WRONGSEC (10016)
[Main Opcode: PUTROOTFH (24)]

Does this provide any light?

Thank you very much for your help!

Felix


---
Felix Rubio
"Don't believe what you're told. Double check."

2020-02-04 19:15:32

by Benjamin Coddington

[permalink] [raw]
Subject: Re: kerberized NFSv4 client reporting operation not permitted when mounting with sec=sys



On 24 Jan 2020, at 11:49, Felix Rubio wrote:

> Hi Benjamin,
>
> I have enabled the debug logging on nfsd by running
>
> When mounting from the client, this is what I get:
>
> [629588.647849] nfsd_dispatch: vers 4 proc 1
> [629588.655615] nfsv4 compound op #1/1: 53 (OP_SEQUENCE)
> [629588.663926] __find_in_sessionid_hashtbl:
> 1579604994:2010353049:95:0
> [629588.675361] nfsd4_sequence: slotid 0
> [629588.679065] check_slot_seqid enter. seqid 644 slot_seqid 643
> [629588.684589] nfsv4 compound op ffff882839705080 opcnt 1 #1: 53:
> status 0
> [629588.691545] nfsv4 compound returned 0
> [629588.695292] --> nfsd4_store_cache_entry slot ffff882806e83000
> [629588.701933] renewing client (clientid 5e26dc02/77d38d99)
> [629591.804857] nfsd_dispatch: vers 4 proc 1
> [629591.809364] nfsv4 compound op #1/4: 53 (OP_SEQUENCE)
> [629591.814944] __find_in_sessionid_hashtbl:
> 1579604994:2010353053:99:0
> [629591.822163] nfsd4_sequence: slotid 0
> [629591.826670] check_slot_seqid enter. seqid 155 slot_seqid 154
> [629591.832771] nfsv4 compound op ffff882839705080 opcnt 4 #1: 53:
> status 0
> [629591.839864] nfsv4 compound op #2/4: 24 (OP_PUTROOTFH)
> [629591.845161] nfsd: fh_compose(exp 08:02/17468677 /export,
> ino=17468677)
> [629591.851706] nfsv4 compound op ffff882839705080 opcnt 4 #2: 24:
> status 10016
> [629591.859660] nfsv4 compound returned 10016

So this is definitely the server returning NFS4ERR_WRONGSEC..

> [629591.864797] --> nfsd4_store_cache_entry slot ffff882838b9e000
> [629591.872968] renewing client (clientid 5e26dc02/77d38d9d)
> [629591.889085] nfsd_dispatch: vers 4 proc 1
> [629591.893713] nfsv4 compound op #1/4: 53 (OP_SEQUENCE)
> [629591.899703] __find_in_sessionid_hashtbl:
> 1579604994:2010353053:99:0
> [629591.906687] nfsd4_sequence: slotid 0
> [629591.912695] check_slot_seqid enter. seqid 156 slot_seqid 155
> [629591.918261] nfsv4 compound op ffff882839705080 opcnt 4 #1: 53:
> status 0
> [629591.924866] nfsv4 compound op #2/4: 22 (OP_PUTFH)
> [629591.931075] nfsd: fh_verify(32: 01060001 63ce4307 5a18c100
> 00000000 00000000 1fba000a)
> [629591.940556] nfsv4 compound op ffff882839705080 opcnt 4 #2: 22:
> status 0
> [629591.948776] nfsv4 compound op #3/4: 3 (OP_ACCESS)
> [629591.954607] nfsd: fh_verify(32: 01060001 63ce4307 5a18c100
> 00000000 00000000 1fba000a)
> [629591.967117] nfsv4 compound op ffff882839705080 opcnt 4 #3: 3:
> status 0
> [629591.975364] nfsv4 compound op #4/4: 9 (OP_GETATTR)
> [629591.980854] nfsd: fh_verify(32: 01060001 63ce4307 5a18c100
> 00000000 00000000 1fba000a)
> [629591.990257] nfsv4 compound op ffff882839705080 opcnt 4 #4: 9:
> status 0
> [629591.996796] nfsv4 compound returned 0
> [629592.001758] --> nfsd4_store_cache_entry slot ffff882838b9e000
> [629592.008061] renewing client (clientid 5e26dc02/77d38d9d)
>
> Using wireshark, this is the log of the packages from/to that ip
> address:
>
> # tshark -i eth0 -p -w /tmp/nfs_mount.cap host 10.1.0.12 and port nfs
> # tshark -r /tmp/nfs_mount.cap
> 1 0.000000000 10.1.0.12 -> 10.0.2.9 NFS 202 V4 Call PUTROOTFH
> | GETATTR

..to this call ^^ ..

> 2 0.000058001 10.0.2.9 -> 10.1.0.12 TCP 54 nfs > rndc [ACK]
> Seq=1 Ack=149 Win=1432 Len=0
> 3 0.074041118 10.0.2.9 -> 10.1.0.12 NFS 146 V4 Reply (Call In
> 1) PUTROOTFH Status: NFS4ERR_WRONGSEC
> 4 0.074927630 10.1.0.12 -> 10.0.2.9 TCP 54 rndc > nfs [ACK]
> Seq=149 Ack=93 Win=1476 Len=0
> 5 0.084223658 10.1.0.12 -> 10.0.2.9 NFS 266 V4 Call ACCESS
> FH: 0xea1b01ae, [Check: RD LU MD XT DL]
> 6 0.084270458 10.0.2.9 -> 10.1.0.12 TCP 54 nfs > rndc [ACK]
> Seq=93 Ack=361 Win=1432 Len=0
> 7 0.208635667 10.0.2.9 -> 10.1.0.12 NFS 254 V4 Reply (Call In
> 5) ACCESS, [Access Denied: RD MD XT DL], [Allowed: LU]
> 8 0.248855020 10.1.0.12 -> 10.0.2.9 TCP 54 rndc > nfs [ACK]
> Seq=361 Ack=293 Win=1498 Len=0
>
> I think the frame of interest is #1, so this is its contents:
> Frame 1: 202 bytes on wire (1616 bits), 202 bytes captured (1616 bits)
> on interface 0
> Interface id: 0
> Encapsulation type: Ethernet (1)
> Arrival Time: Jan 24, 2020 17:39:05.721360043 CET
> [Time shift for this packet: 0.000000000 seconds]
> Epoch Time: 1579883945.721360043 seconds
> [Time delta from previous captured frame: 0.000000000 seconds]
> [Time delta from previous displayed frame: 0.000000000 seconds]
> [Time since reference or first frame: 0.000000000 seconds]
> Frame Number: 1
> Frame Length: 202 bytes (1616 bits)
> Capture Length: 202 bytes (1616 bits)
> [Frame is marked: False]
> [Frame is ignored: False]
> [Protocols in frame: eth:ip:tcp:rpc]
> Ethernet II, Src: 00:81:c4:c1:50:7f (00:81:c4:c1:50:7f), Dst:
> Microsof_44:24:d3 (00:0d:3a:44:24:d3)
> Destination: Microsof_44:24:d3 (00:0d:3a:44:24:d3)
> Address: Microsof_44:24:d3 (00:0d:3a:44:24:d3)
> .... ..0. .... .... .... .... = LG bit: Globally unique
> address (factory default)
> .... ...0 .... .... .... .... = IG bit: Individual address
> (unicast)
> Source: 00:81:c4:c1:50:7f (00:81:c4:c1:50:7f)
> Address: 00:81:c4:c1:50:7f (00:81:c4:c1:50:7f)
> .... ..0. .... .... .... .... = LG bit: Globally unique
> address (factory default)
> .... ...0 .... .... .... .... = IG bit: Individual address
> (unicast)
> Type: IP (0x0800)
> Internet Protocol Version 4, Src: 10.1.0.12 (10.1.0.12), Dst: 10.0.2.9
> (10.0.2.9)
> Version: 4
> Header length: 20 bytes
> Differentiated Services Field: 0x00 (DSCP 0x00: Default; ECN:
> 0x00: Not-ECT (Not ECN-Capable Transport))
> 0000 00.. = Differentiated Services Codepoint: Default (0x00)
> .... ..00 = Explicit Congestion Notification: Not-ECT (Not
> ECN-Capable Transport) (0x00)
> Total Length: 188
> Identification: 0xa3e0 (41952)
> Flags: 0x02 (Don't Fragment)
> 0... .... = Reserved bit: Not set
> .1.. .... = Don't fragment: Set
> ..0. .... = More fragments: Not set
> Fragment offset: 0
> Time to live: 64
> Protocol: TCP (6)
> Header checksum: 0x8046 [validation disabled]
> [Good: False]
> [Bad: False]
> Source: 10.1.0.12 (10.1.0.12)
> Destination: 10.0.2.9 (10.0.2.9)
> Transmission Control Protocol, Src Port: rndc (953), Dst Port: nfs
> (2049), Seq: 1, Ack: 1, Len: 148
> Source port: rndc (953)
> Destination port: nfs (2049)
> [Stream index: 0]
> Sequence number: 1 (relative sequence number)
> [Next sequence number: 149 (relative sequence number)]
> Acknowledgment number: 1 (relative ack number)
> Header length: 20 bytes
> Flags: 0x018 (PSH, ACK)
> 000. .... .... = Reserved: Not set
> ...0 .... .... = Nonce: Not set
> .... 0... .... = Congestion Window Reduced (CWR): Not set
> .... .0.. .... = ECN-Echo: Not set
> .... ..0. .... = Urgent: Not set
> .... ...1 .... = Acknowledgment: Set
> .... .... 1... = Push: Set
> .... .... .0.. = Reset: Not set
> .... .... ..0. = Syn: Not set
> .... .... ...0 = Fin: Not set
> Window size value: 1476
> [Calculated window size: 1476]
> [Window size scaling factor: -1 (unknown)]
> Checksum: 0x4455 [validation disabled]
> [Good Checksum: False]
> [Bad Checksum: False]
> [SEQ/ACK analysis]
> [Bytes in flight: 148]
> Remote Procedure Call, Type:Call XID:0xd17c6210
> Fragment header: Last fragment, 144 bytes
> 1... .... .... .... .... .... .... .... = Last Fragment: Yes
> .000 0000 0000 0000 0000 0000 1001 0000 = Fragment Length: 144
> XID: 0xd17c6210 (3514589712)
> Message Type: Call (0)
> RPC Version: 2
> Program: NFS (100003)
> Program Version: 4
> Procedure: COMPOUND (1)
> Credentials
> Flavor: AUTH_UNIX (1)

.. and the client is using AUTH_UNIX, or sec=sys. Seems your server
isn't
picking up the change to the export for the root for some reason.

How are you modifying the export? What does `exportfs -v` say?

Ben

2020-02-05 11:11:18

by Felix Rubio

[permalink] [raw]
Subject: Re: kerberized NFSv4 client reporting operation not permitted when mounting with sec=sys

Hi Ben,

exportfs -v returns the following output:

/export/home
10.0.0.0/8(sync,wdelay,hide,no_subtree_check,sec=sys:krb5:krb5i:krb5p,rw,secure,root_squash,no_all_squash)

Maybe helps to know that I am using a CentOS 7.7.1908, SELinux enabled,
kernel (provided by CentOS) 3.10.0-1062.9.1.el7.x86_64.

Thank you for your help!
Felix

---
Felix Rubio
"Don't believe what you're told. Double check."

On 2020-02-04 20:14, Benjamin Coddington wrote:
> On 24 Jan 2020, at 11:49, Felix Rubio wrote:
>
>> Hi Benjamin,
>>
>> I have enabled the debug logging on nfsd by running
>>
>> When mounting from the client, this is what I get:
>>
>> [629588.647849] nfsd_dispatch: vers 4 proc 1
>> [629588.655615] nfsv4 compound op #1/1: 53 (OP_SEQUENCE)
>> [629588.663926] __find_in_sessionid_hashtbl:
>> 1579604994:2010353049:95:0
>> [629588.675361] nfsd4_sequence: slotid 0
>> [629588.679065] check_slot_seqid enter. seqid 644 slot_seqid 643
>> [629588.684589] nfsv4 compound op ffff882839705080 opcnt 1 #1: 53:
>> status 0
>> [629588.691545] nfsv4 compound returned 0
>> [629588.695292] --> nfsd4_store_cache_entry slot ffff882806e83000
>> [629588.701933] renewing client (clientid 5e26dc02/77d38d99)
>> [629591.804857] nfsd_dispatch: vers 4 proc 1
>> [629591.809364] nfsv4 compound op #1/4: 53 (OP_SEQUENCE)
>> [629591.814944] __find_in_sessionid_hashtbl:
>> 1579604994:2010353053:99:0
>> [629591.822163] nfsd4_sequence: slotid 0
>> [629591.826670] check_slot_seqid enter. seqid 155 slot_seqid 154
>> [629591.832771] nfsv4 compound op ffff882839705080 opcnt 4 #1: 53:
>> status 0
>> [629591.839864] nfsv4 compound op #2/4: 24 (OP_PUTROOTFH)
>> [629591.845161] nfsd: fh_compose(exp 08:02/17468677 /export,
>> ino=17468677)
>> [629591.851706] nfsv4 compound op ffff882839705080 opcnt 4 #2: 24:
>> status 10016
>> [629591.859660] nfsv4 compound returned 10016
>
> So this is definitely the server returning NFS4ERR_WRONGSEC..
>
>> [629591.864797] --> nfsd4_store_cache_entry slot ffff882838b9e000
>> [629591.872968] renewing client (clientid 5e26dc02/77d38d9d)
>> [629591.889085] nfsd_dispatch: vers 4 proc 1
>> [629591.893713] nfsv4 compound op #1/4: 53 (OP_SEQUENCE)
>> [629591.899703] __find_in_sessionid_hashtbl:
>> 1579604994:2010353053:99:0
>> [629591.906687] nfsd4_sequence: slotid 0
>> [629591.912695] check_slot_seqid enter. seqid 156 slot_seqid 155
>> [629591.918261] nfsv4 compound op ffff882839705080 opcnt 4 #1: 53:
>> status 0
>> [629591.924866] nfsv4 compound op #2/4: 22 (OP_PUTFH)
>> [629591.931075] nfsd: fh_verify(32: 01060001 63ce4307 5a18c100
>> 00000000 00000000 1fba000a)
>> [629591.940556] nfsv4 compound op ffff882839705080 opcnt 4 #2: 22:
>> status 0
>> [629591.948776] nfsv4 compound op #3/4: 3 (OP_ACCESS)
>> [629591.954607] nfsd: fh_verify(32: 01060001 63ce4307 5a18c100
>> 00000000 00000000 1fba000a)
>> [629591.967117] nfsv4 compound op ffff882839705080 opcnt 4 #3: 3:
>> status 0
>> [629591.975364] nfsv4 compound op #4/4: 9 (OP_GETATTR)
>> [629591.980854] nfsd: fh_verify(32: 01060001 63ce4307 5a18c100
>> 00000000 00000000 1fba000a)
>> [629591.990257] nfsv4 compound op ffff882839705080 opcnt 4 #4: 9:
>> status 0
>> [629591.996796] nfsv4 compound returned 0
>> [629592.001758] --> nfsd4_store_cache_entry slot ffff882838b9e000
>> [629592.008061] renewing client (clientid 5e26dc02/77d38d9d)
>>
>> Using wireshark, this is the log of the packages from/to that ip
>> address:
>>
>> # tshark -i eth0 -p -w /tmp/nfs_mount.cap host 10.1.0.12 and port nfs
>> # tshark -r /tmp/nfs_mount.cap
>> 1 0.000000000 10.1.0.12 -> 10.0.2.9 NFS 202 V4 Call PUTROOTFH
>> | GETATTR
>
> ..to this call ^^ ..
>
>> 2 0.000058001 10.0.2.9 -> 10.1.0.12 TCP 54 nfs > rndc [ACK]
>> Seq=1 Ack=149 Win=1432 Len=0
>> 3 0.074041118 10.0.2.9 -> 10.1.0.12 NFS 146 V4 Reply (Call In
>> 1) PUTROOTFH Status: NFS4ERR_WRONGSEC
>> 4 0.074927630 10.1.0.12 -> 10.0.2.9 TCP 54 rndc > nfs [ACK]
>> Seq=149 Ack=93 Win=1476 Len=0
>> 5 0.084223658 10.1.0.12 -> 10.0.2.9 NFS 266 V4 Call ACCESS
>> FH: 0xea1b01ae, [Check: RD LU MD XT DL]
>> 6 0.084270458 10.0.2.9 -> 10.1.0.12 TCP 54 nfs > rndc [ACK]
>> Seq=93 Ack=361 Win=1432 Len=0
>> 7 0.208635667 10.0.2.9 -> 10.1.0.12 NFS 254 V4 Reply (Call In
>> 5) ACCESS, [Access Denied: RD MD XT DL], [Allowed: LU]
>> 8 0.248855020 10.1.0.12 -> 10.0.2.9 TCP 54 rndc > nfs [ACK]
>> Seq=361 Ack=293 Win=1498 Len=0
>>
>> I think the frame of interest is #1, so this is its contents:
>> Frame 1: 202 bytes on wire (1616 bits), 202 bytes captured (1616 bits)
>> on interface 0
>> Interface id: 0
>> Encapsulation type: Ethernet (1)
>> Arrival Time: Jan 24, 2020 17:39:05.721360043 CET
>> [Time shift for this packet: 0.000000000 seconds]
>> Epoch Time: 1579883945.721360043 seconds
>> [Time delta from previous captured frame: 0.000000000 seconds]
>> [Time delta from previous displayed frame: 0.000000000 seconds]
>> [Time since reference or first frame: 0.000000000 seconds]
>> Frame Number: 1
>> Frame Length: 202 bytes (1616 bits)
>> Capture Length: 202 bytes (1616 bits)
>> [Frame is marked: False]
>> [Frame is ignored: False]
>> [Protocols in frame: eth:ip:tcp:rpc]
>> Ethernet II, Src: 00:81:c4:c1:50:7f (00:81:c4:c1:50:7f), Dst:
>> Microsof_44:24:d3 (00:0d:3a:44:24:d3)
>> Destination: Microsof_44:24:d3 (00:0d:3a:44:24:d3)
>> Address: Microsof_44:24:d3 (00:0d:3a:44:24:d3)
>> .... ..0. .... .... .... .... = LG bit: Globally unique
>> address (factory default)
>> .... ...0 .... .... .... .... = IG bit: Individual address
>> (unicast)
>> Source: 00:81:c4:c1:50:7f (00:81:c4:c1:50:7f)
>> Address: 00:81:c4:c1:50:7f (00:81:c4:c1:50:7f)
>> .... ..0. .... .... .... .... = LG bit: Globally unique
>> address (factory default)
>> .... ...0 .... .... .... .... = IG bit: Individual address
>> (unicast)
>> Type: IP (0x0800)
>> Internet Protocol Version 4, Src: 10.1.0.12 (10.1.0.12), Dst: 10.0.2.9
>> (10.0.2.9)
>> Version: 4
>> Header length: 20 bytes
>> Differentiated Services Field: 0x00 (DSCP 0x00: Default; ECN:
>> 0x00: Not-ECT (Not ECN-Capable Transport))
>> 0000 00.. = Differentiated Services Codepoint: Default (0x00)
>> .... ..00 = Explicit Congestion Notification: Not-ECT (Not
>> ECN-Capable Transport) (0x00)
>> Total Length: 188
>> Identification: 0xa3e0 (41952)
>> Flags: 0x02 (Don't Fragment)
>> 0... .... = Reserved bit: Not set
>> .1.. .... = Don't fragment: Set
>> ..0. .... = More fragments: Not set
>> Fragment offset: 0
>> Time to live: 64
>> Protocol: TCP (6)
>> Header checksum: 0x8046 [validation disabled]
>> [Good: False]
>> [Bad: False]
>> Source: 10.1.0.12 (10.1.0.12)
>> Destination: 10.0.2.9 (10.0.2.9)
>> Transmission Control Protocol, Src Port: rndc (953), Dst Port: nfs
>> (2049), Seq: 1, Ack: 1, Len: 148
>> Source port: rndc (953)
>> Destination port: nfs (2049)
>> [Stream index: 0]
>> Sequence number: 1 (relative sequence number)
>> [Next sequence number: 149 (relative sequence number)]
>> Acknowledgment number: 1 (relative ack number)
>> Header length: 20 bytes
>> Flags: 0x018 (PSH, ACK)
>> 000. .... .... = Reserved: Not set
>> ...0 .... .... = Nonce: Not set
>> .... 0... .... = Congestion Window Reduced (CWR): Not set
>> .... .0.. .... = ECN-Echo: Not set
>> .... ..0. .... = Urgent: Not set
>> .... ...1 .... = Acknowledgment: Set
>> .... .... 1... = Push: Set
>> .... .... .0.. = Reset: Not set
>> .... .... ..0. = Syn: Not set
>> .... .... ...0 = Fin: Not set
>> Window size value: 1476
>> [Calculated window size: 1476]
>> [Window size scaling factor: -1 (unknown)]
>> Checksum: 0x4455 [validation disabled]
>> [Good Checksum: False]
>> [Bad Checksum: False]
>> [SEQ/ACK analysis]
>> [Bytes in flight: 148]
>> Remote Procedure Call, Type:Call XID:0xd17c6210
>> Fragment header: Last fragment, 144 bytes
>> 1... .... .... .... .... .... .... .... = Last Fragment: Yes
>> .000 0000 0000 0000 0000 0000 1001 0000 = Fragment Length: 144
>> XID: 0xd17c6210 (3514589712)
>> Message Type: Call (0)
>> RPC Version: 2
>> Program: NFS (100003)
>> Program Version: 4
>> Procedure: COMPOUND (1)
>> Credentials
>> Flavor: AUTH_UNIX (1)
>
> .. and the client is using AUTH_UNIX, or sec=sys. Seems your server
> isn't
> picking up the change to the export for the root for some reason.
>
> How are you modifying the export? What does `exportfs -v` say?
>
> Ben

2020-07-02 14:00:40

by Felix Rubio

[permalink] [raw]
Subject: Re: kerberized NFSv4 client reporting operation not permitted when mounting with sec=sys

Hi everybody

I am resuscitating a call for help that I issued on February. Maybe
somebody can give me a hand? On a NFSv4 server, with kerberos
authentication enabled and working, I have generated a separated export
that I want to export with only sys authentication. I am stuck exactly
at the same point where I was :-/.

This is what I have done, so far:

[root@nfs-server etc]# exportfs -v
/export
10.0.0.0/8(sync,wdelay,hide,crossmnt,no_subtree_check,fsid=0,sec=krb5:krb5i:krb5p,rw,secure,root_squash,no_all_squash)
/export/home
10.0.0.0/8(sync,wdelay,hide,no_subtree_check,sec=krb5:krb5i:krb5p,rw,secure,root_squash,no_all_squash)
/export/smop
10.0.0.0/8(sync,wdelay,hide,no_subtree_check,sec=sys,rw,secure,root_squash,no_all_squash)
/export/scratch
10.0.0.0/8(sync,wdelay,hide,no_subtree_check,sec=sys,rw,secure,root_squash,no_all_squash)

and I still get the same error on the client (here with nfs mount
debugging enabled):
Jul 02 15:13:44 lfd8-Lx kernel: NFS: nfs mount
opts='hard,sec=sys,vers=4.1,addr=10.0.2.9,clientaddr=10.1.0.33'
Jul 02 15:13:44 lfd8-Lx kernel: NFS: parsing nfs mount option 'hard'
Jul 02 15:13:44 lfd8-Lx kernel: NFS: parsing nfs mount option
'sec=sys'
Jul 02 15:13:44 lfd8-Lx kernel: NFS: parsing sec=sys option
Jul 02 15:13:44 lfd8-Lx kernel: NFS: parsing nfs mount option
'vers=4.1'
Jul 02 15:13:44 lfd8-Lx kernel: NFS: parsing nfs mount option
'addr=10.0.2.9'
Jul 02 15:13:44 lfd8-Lx kernel: NFS: parsing nfs mount option
'clientaddr=10.1.0.33'
Jul 02 15:13:44 lfd8-Lx kernel: NFS: MNTPATH: '/smop'
Jul 02 15:13:44 lfd8-Lx kernel: --> nfs4_try_mount()
Jul 02 15:13:44 lfd8-Lx mount[30152]: mount.nfs4: Operation not
permitted
Jul 02 15:13:44 lfd8-Lx kernel: <-- nfs4_try_mount() = -1 [error]

getting a trace on the server with 'tshark -i eth0 -p -w
/tmp/nfs_mount.cap host 10.1.0.33 and port nfs' while running the mount,
I get:
Running as user "root" and group "root". This could be dangerous.
1 0.000000000 10.1.0.33 -> 10.0.2.9 NFS 246 V4 Call GETATTR FH:
0x4bfbf778
2 0.000097402 10.0.2.9 -> 10.1.0.33 NFS 246 V4 Reply (Call In
1) GETATTR
3 0.000790512 10.1.0.33 -> 10.0.2.9 TCP 54 956 > nfs [ACK]
Seq=193 Ack=193 Win=4565 Len=0
4 0.416074043 10.1.0.33 -> 10.0.2.9 NFS 206 V4 Call PUTROOTFH |
GETATTR
5 0.416209445 10.0.2.9 -> 10.1.0.33 NFS 146 V4 Reply (Call In
4) PUTROOTFH Status: NFS4ERR_WRONGSEC
6 0.416853354 10.1.0.33 -> 10.0.2.9 TCP 54 956 > nfs [ACK]
Seq=345 Ack=285 Win=4565 Len=0

And when displaying the frame #4, I get that it is requesting the 'sys'
authentication
Credentials
Flavor: AUTH_UNIX (1)
Length: 36
Stamp: 0x00419352
Machine Name: lfd8-Lx
length: 13
contents: lfd8-Lx
fill bytes: opaque data
but then, in frame #5, it returns NFS4ERR_WRONGSEC.

This is running a CentOS 7.6 (kernel 3.10.0-1127.13.1.el7.x86_64), just
updated and rebooted. SElinux is not enforced.

---
Felix Rubio
"Don't believe what you're told. Double check."

2020-07-02 16:53:10

by Dai Ngo

[permalink] [raw]
Subject: Re: kerberized NFSv4 client reporting operation not permitted when mounting with sec=sys

Hi Felix,

My guess is since '/export' is exported with 'krb5:krb5i:krb5p' and the
exports with 'sys' are underneath it, this might cause the problem when
the mount path of the 'sys' export is traversed on the server. You can
try to move 'smop' and 'sratch' to another subdir.

-Dai

On 7/2/20 6:41 AM, Felix Rubio wrote:
> Hi everybody
>
>     I am resuscitating a call for help that I issued on February.
> Maybe somebody can give me a hand? On a NFSv4 server, with kerberos
> authentication enabled and working, I have generated a separated
> export that I want to export with only sys authentication. I am stuck
> exactly at the same point where I was :-/.
>
> This is what I have done, so far:
>
> [root@nfs-server etc]# exportfs -v
> /export
> 10.0.0.0/8(sync,wdelay,hide,crossmnt,no_subtree_check,fsid=0,sec=krb5:krb5i:krb5p,rw,secure,root_squash,no_all_squash)
> /export/home
> 10.0.0.0/8(sync,wdelay,hide,no_subtree_check,sec=krb5:krb5i:krb5p,rw,secure,root_squash,no_all_squash)
> /export/smop
> 10.0.0.0/8(sync,wdelay,hide,no_subtree_check,sec=sys,rw,secure,root_squash,no_all_squash)
> /export/scratch
> 10.0.0.0/8(sync,wdelay,hide,no_subtree_check,sec=sys,rw,secure,root_squash,no_all_squash)
>
> and I still get the same error on the client (here with nfs mount
> debugging enabled):
> Jul 02 15:13:44 lfd8-Lx kernel: NFS: nfs mount
> opts='hard,sec=sys,vers=4.1,addr=10.0.2.9,clientaddr=10.1.0.33'
> Jul 02 15:13:44 lfd8-Lx kernel: NFS:   parsing nfs mount option 'hard'
> Jul 02 15:13:44 lfd8-Lx kernel: NFS:   parsing nfs mount option 'sec=sys'
> Jul 02 15:13:44 lfd8-Lx kernel: NFS: parsing sec=sys option
> Jul 02 15:13:44 lfd8-Lx kernel: NFS:   parsing nfs mount option
> 'vers=4.1'
> Jul 02 15:13:44 lfd8-Lx kernel: NFS:   parsing nfs mount option
> 'addr=10.0.2.9'
> Jul 02 15:13:44 lfd8-Lx kernel: NFS:   parsing nfs mount option
> 'clientaddr=10.1.0.33'
> Jul 02 15:13:44 lfd8-Lx kernel: NFS: MNTPATH: '/smop'
> Jul 02 15:13:44 lfd8-Lx kernel: --> nfs4_try_mount()
> Jul 02 15:13:44 lfd8-Lx mount[30152]: mount.nfs4: Operation not permitted
> Jul 02 15:13:44 lfd8-Lx kernel: <-- nfs4_try_mount() = -1 [error]
>
> getting a trace on the server with 'tshark -i eth0 -p -w
> /tmp/nfs_mount.cap host 10.1.0.33 and port nfs' while running the
> mount, I get:
> Running as user "root" and group "root". This could be dangerous.
>   1 0.000000000    10.1.0.33 -> 10.0.2.9     NFS 246 V4 Call GETATTR
> FH: 0x4bfbf778
>   2 0.000097402     10.0.2.9 -> 10.1.0.33    NFS 246 V4 Reply (Call In
> 1) GETATTR
>   3 0.000790512    10.1.0.33 -> 10.0.2.9     TCP 54 956 > nfs [ACK]
> Seq=193 Ack=193 Win=4565 Len=0
>   4 0.416074043    10.1.0.33 -> 10.0.2.9     NFS 206 V4 Call PUTROOTFH
> | GETATTR
>   5 0.416209445     10.0.2.9 -> 10.1.0.33    NFS 146 V4 Reply (Call In
> 4) PUTROOTFH Status: NFS4ERR_WRONGSEC
>   6 0.416853354    10.1.0.33 -> 10.0.2.9     TCP 54 956 > nfs [ACK]
> Seq=345 Ack=285 Win=4565 Len=0
>
> And when displaying the frame #4, I get that it is requesting the
> 'sys' authentication
>     Credentials
>         Flavor: AUTH_UNIX (1)
>         Length: 36
>         Stamp: 0x00419352
>         Machine Name: lfd8-Lx
>             length: 13
>             contents: lfd8-Lx
>             fill bytes: opaque data
> but then, in frame #5, it returns NFS4ERR_WRONGSEC.
>
> This is running a CentOS 7.6 (kernel 3.10.0-1127.13.1.el7.x86_64),
> just updated and rebooted. SElinux is not enforced.
>
> ---
> Felix Rubio
> "Don't believe what you're told. Double check."

2020-07-02 17:53:10

by Felix Rubio

[permalink] [raw]
Subject: Re: kerberized NFSv4 client reporting operation not permitted when mounting with sec=sys

Thank you Dai,

Your guess is absolutely correct: Right after I send the mail, I noted that... I set it the /exports (fsid=0) to sec=*sys:*krb5:krb5i:krb5p, and then I set the depending FS to the options I wanted: fixed. I even told Benjamin Coddington, out of the happines for having solved it (it was really making me go nuts), but I forgot to tell the mailing list. Sorry for that!

Thank you very much, guys!

Felix


2020-07-06 17:18:43

by J. Bruce Fields

[permalink] [raw]
Subject: Re: kerberized NFSv4 client reporting operation not permitted when mounting with sec=sys

On Thu, Jul 02, 2020 at 07:52:41PM +0200, Felix Rubio wrote:
> Your guess is absolutely correct: Right after I send the mail, I noted that... I set it the /exports (fsid=0) to sec=*sys:*krb5:krb5i:krb5p, and then I set the depending FS to the options I wanted: fixed. I even told Benjamin Coddington, out of the happines for having solved it (it was really making me go nuts), but I forgot to tell the mailing list. Sorry for that!

Note, by the way, that fsid=0 thing was required for nfsv4 exports years
ago, but no longer is. It's usually better not to bother with that.

--b.

2020-07-06 20:05:43

by Patrick Goetz

[permalink] [raw]
Subject: Re: kerberized NFSv4 client reporting operation not permitted when mounting with sec=sys

On 7/6/20 12:18 PM, J. Bruce Fields wrote:
>
> Note, by the way, that fsid=0 thing was required for nfsv4 exports years
> ago, but no longer is. It's usually better not to bother with that.
>


Are we ever going to get some solid up-to-date NFSv4/pNFS documentation?
I'm sufficiently frustrated to write it myself, but am not 100% sure
where to start.


2020-07-06 20:30:36

by J. Bruce Fields

[permalink] [raw]
Subject: Re: kerberized NFSv4 client reporting operation not permitted when mounting with sec=sys

On Mon, Jul 06, 2020 at 02:57:52PM -0500, Patrick Goetz wrote:
> On 7/6/20 12:18 PM, J. Bruce Fields wrote:
> >
> >Note, by the way, that fsid=0 thing was required for nfsv4 exports years
> >ago, but no longer is. It's usually better not to bother with that.
>
> Are we ever going to get some solid up-to-date NFSv4/pNFS
> documentation? I'm sufficiently frustrated to write it myself, but
> am not 100% sure where to start.

I guess the places I'd start would be the man pages (original source is
nfs-utils, git://linux-nfs.org/~steved/nfs-utils) or wiki.linux-nfs.org.

But, I don't know, you may be in a better place to position to know what
gaps you want filled--where are you looking for documentation, and what
are you not finding?

--b.

2020-07-07 15:21:13

by Patrick Goetz

[permalink] [raw]
Subject: Re: kerberized NFSv4 client reporting operation not permitted when mounting with sec=sys



On 7/6/20 3:27 PM, J. Bruce Fields wrote:
> On Mon, Jul 06, 2020 at 02:57:52PM -0500, Patrick Goetz wrote:
>> On 7/6/20 12:18 PM, J. Bruce Fields wrote:
>>>
>>> Note, by the way, that fsid=0 thing was required for nfsv4 exports years
>>> ago, but no longer is. It's usually better not to bother with that.
>>
>> Are we ever going to get some solid up-to-date NFSv4/pNFS
>> documentation? I'm sufficiently frustrated to write it myself, but
>> am not 100% sure where to start.
>
> I guess the places I'd start would be the man pages (original source is
> nfs-utils, git://linux-nfs.org/~steved/nfs-utils) or wiki.linux-nfs.org.
>
> But, I don't know, you may be in a better place to position to know what
> gaps you want filled--where are you looking for documentation, and what
> are you not finding?
>
> --b.
>

Well, a good example is the fsid=0 thing. Where is it documented that
this is no longer needed? I'm 100% certain I've read through all the
man pages I could find several times.

2020-07-07 15:52:24

by J. Bruce Fields

[permalink] [raw]
Subject: Re: kerberized NFSv4 client reporting operation not permitted when mounting with sec=sys

On Tue, Jul 07, 2020 at 10:10:07AM -0500, Patrick Goetz wrote:
>
>
> On 7/6/20 3:27 PM, J. Bruce Fields wrote:
> >On Mon, Jul 06, 2020 at 02:57:52PM -0500, Patrick Goetz wrote:
> >>On 7/6/20 12:18 PM, J. Bruce Fields wrote:
> >>>
> >>>Note, by the way, that fsid=0 thing was required for nfsv4 exports years
> >>>ago, but no longer is. It's usually better not to bother with that.
> >>
> >>Are we ever going to get some solid up-to-date NFSv4/pNFS
> >>documentation? I'm sufficiently frustrated to write it myself, but
> >>am not 100% sure where to start.
> >
> >I guess the places I'd start would be the man pages (original source is
> >nfs-utils, git://linux-nfs.org/~steved/nfs-utils) or wiki.linux-nfs.org.
> >
> >But, I don't know, you may be in a better place to position to know what
> >gaps you want filled--where are you looking for documentation, and what
> >are you not finding?
> >
> >--b.
> >
>
> Well, a good example is the fsid=0 thing. Where is it documented
> that this is no longer needed? I'm 100% certain I've read through
> all the man pages I could find several times.

For man pages, this belongs in exports(5). Looks like the description
of the "fsid" option in exports(5) is out of date.

Might also be worth googling around to see if there are some HOWTO's out
there that could be updated.

You can find out when the change was made by grepping for
"NFSEXP_V4ROOT" in kernel and nfs-utils source. Looks like it was 2009,
kernel and nfs-utils versions 2.6.33 and 1.2.2 respectively.

--b.