Bug 230095

(In reply to comment #0)
> 
> Version-Release number of selected component (if applicable):
> autofs-5.0.1-0.rc3.21
> 

Can you update to revision 22 or above please.

Ian

Still happens with autofs-5.0.1-0.rc3.23

(In reply to comment #2)
> Still happens with autofs-5.0.1-0.rc3.23

autofs-5.0.1-0.rc3.25 is on it's way to testing.
Can you try that revision please.

Ian

Still happens with -25.  Running in debug mode, this is what I see:

Mar  7 13:55:32 saga automount[10410]: attempting to mount entry /data/sw1
Mar  7 13:55:32 saga automount[10410]: lookup_name_file_source_instance: file
map not found
Mar  7 13:55:32 saga automount[10410]: mounted /data/sw1
Mar  7 13:55:32 saga automount[10410]: do_mount_indirect: indirect trigger not
valid or already mounted /data/sw1/fedora

And it does end up getting mounted:

/export/data1 on /data/sw1 type none (rw,bind)

but not before the find command fails.

Appears to not be limited to bind mount, but does seem linked to using "find". 
perhaps the way it accesses directories is the issue?

open("/data/sw1", O_RDONLY|O_LARGEFILE) = 4
fchdir(4)                               = 0
close(4)                                = 0
lstat64("fedora", 0xbfe98ce8)           = -1 ENOENT (No such file or directory)

(In reply to comment #5)
> Appears to not be limited to bind mount, but does seem linked to using "find". 
> perhaps the way it accesses directories is the issue?
> 
> open("/data/sw1", O_RDONLY|O_LARGEFILE) = 4
> fchdir(4)                               = 0
> close(4)                                = 0
> lstat64("fedora", 0xbfe98ce8)           = -1 ENOENT (No such file or directory)
> 

But I've tried using find and I can't reproduce it.

What other information about the configuration and
client can you give me?

Does this suddenly work if the NFS server is running?
Add an export for some, possibly unrelated directory
and check.

Ian

Did you notice comment #6?
If you can make some time to check this that would be great.

Ian

Not sure what else I can give you, but here goes.  I'm testing with FC6 server
and client.

auto.master (on nfs client):
/misc   /etc/auto.misc
/net    -hosts
+auto.master

auto.master (on nfs server - saga):
/data   auto.datag      intr
/data4  auto.data4g     fstype=nfs4,intr,rsize=32768,wsize=32768
+auto.master

nis auto.master:
/data auto.data intr
/home auto.home intr
/nfs auto.nfs   intr,rsize=8192,wsize=8192
/data4 auto.data4       fstype=nfs4,intr,rsize=32768,wsize=32768

auto.data and auto.datag are nis maps.

sw1 entry (in auto.data):
sw1 saga:/export/data1

sw1 entry (in auto.datag):
sw1 sagag:/export/data1


Some more debug info:

Mar 27 10:44:00 saga automount[3089]: handle_packet: type = 3
Mar 27 10:44:00 saga automount[3089]: handle_packet_missing_indirect: token
4081, name sw1, request pid 14253
Mar 27 10:44:00 saga automount[3089]: attempting to mount entry /data/sw1
Mar 27 10:44:00 saga automount[3089]: lookup_name_file_source_instance: file map
not found
Mar 27 10:44:00 saga automount[3089]: lookup_mount: lookup(yp): looking up sw1
Mar 27 10:44:00 saga automount[3089]: lookup_mount: lookup(yp): sw1 ->
sagag:/export/data1
Mar 27 10:44:00 saga automount[3089]: parse_mount: parse(sun): expanded entry:
sagag:/export/data1
Mar 27 10:44:00 saga automount[3089]: parse_mount: parse(sun): gathered options:
intr
Mar 27 10:44:00 saga automount[3089]: parse_mount: parse(sun):
dequote("sagag:/export/data1") -> sagag:/export/data1
Mar 27 10:44:00 saga automount[3089]: parse_mount: parse(sun): core of entry:
options=intr, loc=sagag:/export/data1
Mar 27 10:44:00 saga automount[3089]: sun_mount: parse(sun): mounting root
/data, mountpoint sw1, what sagag:/export/data1, fstype nfs, options intr
Mar 27 10:44:00 saga automount[3089]: mount_mount: mount(nfs): root=/data
name=sw1 what=sagag:/export/data1, fstype=nfs, options=intr
Mar 27 10:44:00 saga automount[3089]: mount_mount: mount(nfs): nfs
options="intr", nosymlink=0, ro=0
Mar 27 10:44:00 saga automount[3089]: mount_mount: mount(nfs): calling
mkdir_path /data/sw1
Mar 27 10:44:00 saga automount[3089]: mount_mount: mount(nfs): sw1 is local,
attempt bind mount
Mar 27 10:44:00 saga automount[3089]: mount_mount: mount(bind): calling
mkdir_path /data/sw1
Mar 27 10:44:00 saga automount[3089]: mount_mount: mount(bind): calling mount
--bind -s  -o defaults /export/data1 /data/sw1
Mar 27 10:44:00 saga automount[3089]: mount_mount: mount(bind): mounted
/export/data1 type bind on /data/sw1
Mar 27 10:44:00 saga automount[3089]: send_ready: token = 4081
Mar 27 10:44:00 saga automount[3089]: mounted /data/sw1
Mar 27 10:44:00 saga automount[3089]: handle_packet: type = 3
Mar 27 10:44:00 saga automount[3089]: handle_packet_missing_indirect: token
4082, name sw1/fedora, request pid 14253
Mar 27 10:44:00 saga automount[3089]: do_mount_indirect: indirect trigger not
valid or already mounted /data/sw1/fedora

This was the result of:

[root@saga log]# umount /data/sw1
[root@saga log]# find /data/sw1/fedora -name blah
find: /data/sw1/fedora: No such file or directory
[root@saga log]# find /data/sw1/fedora -name blah
(succeeded)

Can get the same when run from a client machine:

[root@cynosure ~]# umount /data/sw1
[root@cynosure ~]# find /data/sw1/fedora -name blah
find: /data/sw1/fedora: No such file or directory
[root@cynosure ~]# find /data/sw1/fedora -name blah

But, say "ls" will always work:

[root@cynosure ~]# umount /data/sw1
[root@cynosure ~]# ls /data/sw1/fedora
cora            fedora-core-4  livna                      RPM-GPG-KEY.fr
core            fedora-core-5  pungi                      RPM-GPG-KEY-fwupdate
....

The mount always happens, but not before find decides that the directory doesn't
exist.

If I try find on the mountpoint itself it works, although you get a warning:

[root@cynosure ~]# find /data/sw1 -name blah
find: WARNING: Hard link count is wrong for /data/sw1: this may be a bug in your
filesystem driver.  Automatically turning on find's -noleaf option.  Earlier
results may have failed to include directories that should have been searched.

Again, probably has to do with the way the directory is accessed by find and
mentioned in comment 5 (open parent dir, do lstat64).  In comparison, ls opens
the directory directly rather than the parent directory:

open("/data/sw1/fedora", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY) = 3
fstat64(3, {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
fcntl64(3, F_SETFD, FD_CLOEXEC)         = 0
mmap2(NULL, 135168, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
0xb7c4e000
getdents64(3, /* 30 entries */, 131072) = 1048
getdents64(3, /* 0 entries */, 131072)  = 0
munmap(0xb7c4e000, 135168)              = 0
close(3)                                = 0

Based on the date this bug was created, it appears to have been reported
against rawhide during the development of a Fedora release that is no
longer maintained. In order to refocus our efforts as a project we are
flagging all of the open bugs for releases which are no longer
maintained. If this bug remains in NEEDINFO thirty (30) days from now,
we will automatically close it.

If you can reproduce this bug in a maintained Fedora version (7, 8, or
rawhide), please change this bug to the respective version and change
the status to ASSIGNED. (If you're unable to change the bug's version
or status, add a comment to the bug and someone will change it for you.)

Thanks for your help, and we apologize again that we haven't handled
these issues to this point.

The process we're following is outlined here:
http://fedoraproject.org/wiki/BugZappers/F9CleanUp

We will be following the process here:
http://fedoraproject.org/wiki/BugZappers/HouseKeeping to ensure this
doesn't happen again.

This still happens with current Fedora 8

(In reply to comment #10)
> This still happens with current Fedora 8

Very interesting.

We're working on another report almost the same as this
one. The log entries are a little different but it looks
like it could be the same bug and this may provide us a
way to reproduce it (we're having trouble at the moment).

I'll get back if we make progress.

Ian

(In reply to comment #11)
> (In reply to comment #10)
> > This still happens with current Fedora 8
> 
> Very interesting.
> 
> We're working on another report almost the same as this
> one. The log entries are a little different but it looks
> like it could be the same bug and this may provide us a
> way to reproduce it (we're having trouble at the moment).
> 
> I'll get back if we make progress.

And still, for some unknown reason, I can't reproduce it
and you can, *sigh*.

Ian

(In reply to comment #12)
> > I'll get back if we make progress.
> 
> And still, for some unknown reason, I can't reproduce it
> and you can, *sigh*.

How many directories are contained in /export/data1 and
/export/data1/fedora?

Ian

[root@saga data1]# ls -l /export/data1 | wc -l
36
[root@saga data1]# ls -l /export/data1/fedora | wc -l
68
[root@saga data1]# ls -l /export/data1 | grep ^d | wc -l
18
[root@saga data1]# ls -l /export/data1/fedora | grep ^d | wc -l
8

Could you also tell us which kernel you are running, please?

Ian, this sounds a lot like the bug in RHEL 5.1 GA, where the first access would
fail and subsequent accesses would always work.

2.6.24.5-85.fc8

(In reply to comment #17)
> 2.6.24.5-85.fc8

OK, I just checked the sources for the kernel you're running, and it does not
contain the bug that we had in RHEL 5.1 GA.  So, it may be the other ENOENT
issue Ian mentioned we were chasing.

This appears to be fixed with:

kernel-2.6.27.4-26.fc9.i686
autofs-5.0.3-27.i386

Still broken on latest F-8.

(In reply to comment #19)
> This appears to be fixed with:
> 
> kernel-2.6.27.4-26.fc9.i686
> autofs-5.0.3-27.i386
> 
> Still broken on latest F-8.

There were around 20 autofs4 patches included in 2.6.27.
I don't think F-8 will get a 2.6.27 kernel.
All I can do is offer patches but then you would need to
build a custom kernel.

Ian

I'm fine with it being fixed in F-9.  We'll hopefully be moving to F-10 soon.