Bug 612790

Summary: Regression for confusing 'mount request from unknown host' messages
Product: Red Hat Enterprise Linux 6 Reporter: yanfu,wang <yanwang>
Component: nfs-utilsAssignee: Steve Dickson <steved>
Status: CLOSED NOTABUG QA Contact: yanfu,wang <yanwang>
Severity: medium Docs Contact:
Priority: medium    
Version: 6.0CC: bfields, jiyin, jlayton, rwheeler
Target Milestone: rcKeywords: Regression
Target Release: 6.0   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2010-11-22 16:27:38 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 463578    
Bug Blocks:    

Description yanfu,wang 2010-07-09 02:39:25 UTC
seems there is a regression problem for bz 463578 run against rhel6 beta2, pls refer to below:
Steps to Reproduce:
# uname -a
Linux dell-pe2550-01.rhts.eng.bos.redhat.com 2.6.32-42.el6.i686 #1 SMP
Wed Jun 30 15:39:29 EDT 2010 i686 i686 i386 GNU/Linux

# rpm -qa |grep nfs-utils
nfs-utils-lib-1.1.5-1.el6.i686
nfs-utils-1.2.2-4.el6.i686

# cat /etc/exports 
/tmp bugzilla.redhat.com(ro)

# showmount -e localhost
Export list for localhost:
/tmp bugzillavip.proxy.prod.ext.phx2.redhat.com

# rpc.mountd -F -d all
mountd: v4root_create: path '/'
mountd: auth_unix_ip: inbuf 'nfsd 127.0.0.1'
mountd: auth_unix_ip: client (nil) 'DEFAULT'

# tail /var/log/messages 
Jul  8 01:36:31 dell-pe2550-01 mountd[5164]: Caught signal 15,
un-registering and exiting.
Jul  8 01:36:31 dell-pe2550-01 kernel: nfsd: last server has exited,
flushing export cache
Jul  8 01:36:31 dell-pe2550-01 kernel: NFSD:
Using /var/lib/nfs/v4recovery as the NFSv4 state recovery directory
Jul  8 01:36:31 dell-pe2550-01 kernel: NFSD: starting 90-second grace
period

# strace mount -t nfs localhost:/tmp /mnt
execve("/bin/mount", ["mount", "-t", "nfs", "localhost:/tmp", "/mnt"],
[/* 26 vars */]) = 0
brk(0)                                  = 0x1e2b000
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0xb783f000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or
directory)
open("/etc/ld.so.cache", O_RDONLY)      = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=30257, ...}) = 0
mmap2(NULL, 30257, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7837000
close(3)                                = 0
open("/lib/libblkid.so.1", O_RDONLY)    = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0@5\0\0004\0\0
\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=136188, ...}) = 0
mmap2(NULL, 138920, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
0) = 0x110000
mmap2(0x130000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|
MAP_DENYWRITE, 3, 0x1f) = 0x130000
close(3)                                = 0
open("/lib/libuuid.so.1", O_RDONLY)     = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\0\17\0\0004\0\0
\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=14956, ...}) = 0
mmap2(NULL, 17584, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0)
= 0x223000
mmap2(0x227000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|
MAP_DENYWRITE, 3, 0x3) = 0x227000
close(3)                                = 0
open("/lib/libselinux.so.1", O_RDONLY)  = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\20B\0\0004\0\0
\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=120764, ...}) = 0
mmap2(NULL, 125948, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
0) = 0x9fb000
mmap2(0xa18000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|
MAP_DENYWRITE, 3, 0x1c) = 0xa18000
close(3)                                = 0
open("/lib/libsepol.so.1", O_RDONLY)    = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\0000\0\0004\0\0
\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=244320, ...}) = 0
mmap2(NULL, 244448, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
0) = 0xf11000
mmap2(0xf4c000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|
MAP_DENYWRITE, 3, 0x3b) = 0xf4c000
close(3)                                = 0
open("/lib/libc.so.6", O_RDONLY)        = 3
read(3, "\177ELF\1\1\1\3\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0 n\1\0004\0\0
\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=1852084, ...}) = 0
mmap2(NULL, 1620360, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
0) = 0x59b000
mprotect(0x720000, 4096, PROT_NONE)     = 0
mmap2(0x721000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|
MAP_DENYWRITE, 3, 0x185) = 0x721000
mmap2(0x724000, 10632, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|
MAP_ANONYMOUS, -1, 0) = 0x724000
close(3)                                = 0
open("/lib/libdl.so.2", O_RDONLY)       = 3
read(3, "\177ELF\1\1\1\3\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0`\n\0\0004\0\0
\0"..., 512) = 512
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0xb7836000
fstat64(3, {st_mode=S_IFREG|0755, st_size=17892, ...}) = 0
mmap2(NULL, 16500, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0)
= 0xfa0000
mmap2(0xfa3000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|
MAP_DENYWRITE, 3, 0x2) = 0xfa3000
close(3)                                = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0xb7835000
set_thread_area({entry_number:-1 -> 6, base_addr:0xb7835750,
limit:1048575, seg_32bit:1, contents:0, read_exec_only:0,
limit_in_pages:1, seg_not_present:0, useable:1}) = 0
mprotect(0xfa3000, 4096, PROT_READ)     = 0
mprotect(0x721000, 8192, PROT_READ)     = 0
mprotect(0xa18000, 4096, PROT_READ)     = 0
mprotect(0x307000, 4096, PROT_READ)     = 0
munmap(0xb7837000, 30257)               = 0
statfs64("/selinux", 84, {f_type=0xf97cff8c, f_bsize=4096, f_blocks=0,
f_bfree=0, f_bavail=0, f_files=0, f_ffree=0, f_fsid={0, 0},
f_namelen=255, f_frsize=4096}) = 0
brk(0)                                  = 0x1e2b000
brk(0x1e4c000)                          = 0x1e4c000
open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=99158720, ...}) = 0
mmap2(NULL, 2097152, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7635000
mmap2(NULL, 262144, PROT_READ, MAP_PRIVATE, 3, 0x2d7f) = 0xb75f5000
mmap2(NULL, 1392640, PROT_READ, MAP_PRIVATE, 3, 0x3270) = 0xb74a1000
close(3)                                = 0
umask(022)                              = 022
open("/dev/null", O_RDWR|O_LARGEFILE)   = 3
close(3)                                = 0
getuid32()                              = 0
geteuid32()                             = 0
stat64("/sbin/mount.nfs", {st_mode=S_IFREG|S_ISUID|0755,
st_size=120064, ...}) = 0
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|
SIGCHLD, child_tidptr=0xb78357b8) = 5240
wait4(-1, mount.nfs: access denied by server while mounting
localhost:/tmp
[{WIFEXITED(s) && WEXITSTATUS(s) == 32}], 0, NULL) = 5240
--- SIGCHLD (Child exited) @ 0 (0) ---
exit_group(32)            

Expected result:
"refused %s request from %s for %s (%s):unmatched host" should be logged.

Actual result:
There isn't "unmatched host" info logged, but seem the source
code have the error message by checking nfs-utils-1.2.2-4.el6.src.rpm:
...
        case unknown_host:
                xlog(L_WARNING, "refused %s request from %s for %s (%s):
unmatched host",
                     what, inet_ntoa(addr), path, epath);
                break;
...


Additional info:
rhts jobs links:
run against rhel5:
http://rhts.redhat.com/cgi-bin/rhts/test_log.cgi?id=15133718, pass

run against rhel6:
http://rhts.redhat.com/cgi-bin/rhts/test_log.cgi?id=15042945, fail

Comment 1 Steve Dickson 2010-07-21 15:23:23 UTC
I am not seeing this with nfs-utils-1.2.2-4.el6.x86_64:

# cat /etc/exports 
/home vrhel6(rw)
# service nfs start
# mount localhost:/home /mnt/tmp
[The mount works] 
# umount /mnt/tmp

[Change the export to some other host]
# cat /etc/exports 
/home tophat(rw)
# exportfs -arv
exporting tophat:/home
# mount localhost:/home /mnt/tmp
mount.nfs: access denied by server while mounting localhost:/home
[Fails as expected]

Comment 2 yanfu,wang 2010-07-22 03:37:01 UTC
(In reply to comment #1)
> I am not seeing this with nfs-utils-1.2.2-4.el6.x86_64:
> 
> # cat /etc/exports 
> /home vrhel6(rw)
> # service nfs start
> # mount localhost:/home /mnt/tmp
> [The mount works] 
> # umount /mnt/tmp
> 
> [Change the export to some other host]
> # cat /etc/exports 
> /home tophat(rw)
> # exportfs -arv
> exporting tophat:/home
> # mount localhost:/home /mnt/tmp
> mount.nfs: access denied by server while mounting localhost:/home
> [Fails as expected]    

hi Steve,
I think you should check the /var/log/message, "refused %s request from %s for %s (%s):unmatched host" should be logged in there according to the source.

Comment 4 Steve Dickson 2010-08-03 16:01:10 UTC
I'm sorry but I am not able to reproduce this message...

Comment 5 yanfu,wang 2010-08-04 04:59:15 UTC
(In reply to comment #4)
> I'm sorry but I am not able to reproduce this message...    

hi Steve,
you can schedule job by simply run below:
# kernel_workflow.py -a i386 -t /CoreOS/nfs-utils/Sanity/bz463578-confusing-mount-request-from-unknown-host -u your_mail_address -d RHEL6.0-Snapshot-9  -S rhts.redhat.com -s -w "/CoreOS/nfs-utils/Sanity/bz463578-confusing-mount-request-from-unknown-host" -l -s

I've scheduled it against rhel6-snapshot9 and it's failed again:
http://rhts.redhat.com/cgi-bin/rhts/test_log.cgi?id=15826421

and the bug cloned from bug 463578, I thinks the above manual steps means mountd has a list of hosts that it knows that it builds from /etc/exports, for example:
# cat /etc/exports 
/tmp bugzilla.redhat.com(ro)

If the mount request doesn't match any of those hosts, for example:
# mount -t nfs localhost:/tmp /mnt

note it's not "bugzilla.redhat.com" specified in /etc/exports,
then you'll get the "refused %s request from %s for %s (%s):unmatched host" message in syslog, but there aren't umatch error be logged ,maybe something is causing it to skip the message for some reason.

Comment 8 J. Bruce Fields 2010-11-22 16:27:38 UTC
I believe the current behavior is preferred: logging a server-side error by default on every mount that fails from a client makes it too easy for an unauthorized client to fill the server's logs.

If an administrator would like to get those messages anyway, they should be able to by turning on debugging with the -d option to rpc.mountd.

Client-side errors are more helpful here in most cases, as they provide immediate feedback to whoever attempts the mount.  The current error message from mount looks adequate to me.

Suggestions welcomed for improvements to the client error message or the optional server-side debugging, but those should be separate bugs.

Closed unless someone wants to disagree.

Comment 9 yanfu,wang 2010-11-23 08:54:32 UTC
(In reply to comment #8)
> I believe the current behavior is preferred: logging a server-side error by
> default on every mount that fails from a client makes it too easy for an
> unauthorized client to fill the server's logs.
> 
> If an administrator would like to get those messages anyway, they should be
> able to by turning on debugging with the -d option to rpc.mountd.
> 
> Client-side errors are more helpful here in most cases, as they provide
> immediate feedback to whoever attempts the mount.  The current error message
> from mount looks adequate to me.
> 
> Suggestions welcomed for improvements to the client error message or the
> optional server-side debugging, but those should be separate bugs.
> 
> Closed unless someone wants to disagree.

ok, maybe the behavior on rhel6 is different from https://bugzilla.redhat.com/show_bug.cgi?id=463578#c2 for rhel5, I could get "refused %s request from %s for
%s (%s):unmatched host" logged in /var/log/messages without turning on debug or any extra operation on rhel5.