Ian Kent wrote:
> On Fri, 2007-10-05 at 17:14 -0400, Dan Halbert wrote:
>> I have what looks like an automount race condition, and am very puzzled...
>>
>> The first time I reference an automounted file, it is not there
>> (ENOENT). On the second and later try, the file is there...
>
> We really must have a debug log, include everything and give some
> indication of when the problem occurred....
Details you requested follow.
Thanks very much. I have reproduced the problem and have a debug log.
Interestingly, I could not reproduce it with a file map, but could with an ldap
map. However, that may be a red herring (see below).
I don't see any obvious differences in the debug log below between
the good case and the bad case (ENOENT), but perhaps I've missed something.
As you can see below in the behavior section, the first time catting the file
works for both the file map and the ldap map.
The second time for the ldap map is when I get the ENOENT. It's as if the kernel
thinks the directory (u10, in this case) is still there, but has nothing in it,
even though it has been previously umounted. I'm not sure if it is the automount
daemon that is at fault, as it seems to be doing the same thing in both cases.
If it's an unintentional race condition between the kernel and the automount
daemon, perhaps the ldap lookup delay causes the race to be revealed, and so
maybe the problem is not ldap per se.
Another odd note:
I -have- reproduced the ENOENT with a file map and starting /usr/sbin/automount
by hand with appropriate arguments. However, I had to have done "service start
automount"
beforehand, so there were a number of other automount daemons running (which
used ldap).
If I started a /usr/sbin/automount by hand after "service stop automount", with
no
other automount daemons running, I cannot reproduce the problem.
To repeat something from my previous message, I don't see the problem with
autofs-5.0.1-0.rc2.43.0.2 on an CentOS 5 system.
Thanks,
Dan
-----------------------------------------------------------------------------
This is the behavior I see:
##### Start automount fresh.
# service autofs start
Starting automount: [ OK ]
##### cat a file reachable via automount with a file map. That works fine.
# cat /mnt-via-file/u10/test
Contents of test.
##### Umount and try again. Works fine.
# umount /mnt-via-file/u10
# cat /mnt-via-file/u10/test
Contents of test.
# umount /mnt-via-file/u10
##### Now try the same thing with an ldap map. The first time, it works.
# cat /mnt-via-ldap/u10/test
Contents of test.
##### Unmount and try again. The second time
##### cat does not see the file (ENOENT)! *********
# umount /mnt-via-ldap/u10
# cat /mnt-via-ldap/u10/test
cat: /mnt-via-ldap/u10/test: No such file or directory
##### Try again, and the file is now there.
# cat /mnt-via-ldap/u10/test
Contents of test.
----------------------------------------------------------------------
autofs version:
autofs-4.1.3-199.3
(I also reproduced the problem with autofs-4.1.3-214, the latest version
at jmoyer's webpage.)
----------------------------------------------------------------------
kernel:
2.6.9-55.0.9.ELsmp x86_64
----------------------------------------------------------------------
/etc/auto.master (comments removed):
/mnt-via-file /etc/auto.mnt -rw,hard,intr --ghost --timeout=3333 --debug
/mnt-via-ldap ldap:ou=auto.podraid2,ou=autofs,dc=podzinger,dc=local
-rw,hard,intr --ghost --timeout=4444 --debug
----------------------------------------------------------------------
/etc/auto.mnt (referenced in auto.master above). It's meant to be
the same as the ldap map below.
* podraid2.podzinger.local:/export/&
----------------------------------------------------------------------
auto.podraid2 map from ldap (in LDIF format):
dn: cn=*,ou=auto.podraid2,ou=autofs,dc=podzinger,dc=local
cn: *
objectClass: automount
automountInformation: podraid2.podzinger.local:/export/&
----------------------------------------------------------------------
/etc/nsswitch.conf (comments and blank lines removed):
passwd: files ldap
shadow: files ldap
group: files ldap
hosts: files dns
bootparams: files
ethers: files
netmasks: files
networks: files
protocols: files ldap
rpc: files
services: files ldap
netgroup: files ldap
publickey: files
automount: files ldap
aliases: files
----------------------------------------------------------------------
/etc/sysconfig/autofs (comments removed):
(we have not modified this):
LOCALOPTIONS=""
DAEMONOPTIONS="--timeout=60"
LDAPAUTOMASTER=""
UNDERSCORETODOT=1
DISABLE_DIRECT=1
ONE_AUTO_MASTER=0
GHOSTDIRS=""
BASEDN=
OLD_LDAP_LOOKUP=0
----------------------------------------------------------------------
Finally, the debug log. I have interspersed the commands in the example
above to show you what happens at what point:
######################################################################
# service autofs start
Starting automount: [ OK ]
######################################################################
Oct 6 17:48:40 dev-worker-05 automount[901]: starting automounter version
4.1.3-199.3, path = /mnt-via-file, maptype = file, mapname = /etc/auto.mnt
Oct 6 17:48:40 dev-worker-05 automount[901]: parse(sun): init gathered
options: rw,hard,intr
Oct 6 17:48:40 dev-worker-05 automount[901]: mount(bind): bind_works = 1
Oct 6 17:48:40 dev-worker-05 automount[901]: using kernel protocol version 4.00
Oct 6 17:48:40 dev-worker-05 automount[901]: using timeout 3333 seconds; freq
834 secs
Oct 6 17:48:40 dev-worker-05 automount[901]: lookup(file): Adding map
/etc/auto.mnt,/etc/auto.mnt
Oct 6 17:48:40 dev-worker-05 automount[901]: added map name="/etc/auto.mnt",
entry="/etc/auto.mnt" to context
Oct 6 17:48:40 dev-worker-05 automount[901]: ghosting enabled
Oct 6 17:48:40 dev-worker-05 automount[960]: starting automounter version
4.1.3-199.3, path = /mnt-via-ldap, maptype = ldap, mapname =
ou=auto.podraid2,ou=autofs,dc=podzinger,dc=local
Oct 6 17:48:40 dev-worker-05 automount[960]: lookup(ldap): server =
"(default)", port = 389, base dn =
"ou=auto.podraid2,ou=autofs,dc=podzinger,dc=local"
Oct 6 17:48:40 dev-worker-05 automount[960]: parse(sun): init gathered
options: rw,hard,intr
Oct 6 17:48:40 dev-worker-05 automount[960]: mount(bind): bind_works = 1
Oct 6 17:48:40 dev-worker-05 automount[960]: using kernel protocol version 4.00
Oct 6 17:48:40 dev-worker-05 automount[960]: using timeout 4444 seconds; freq
1111 secs
Oct 6 17:48:40 dev-worker-05 automount[960]: lookup(ldap): searching for
"(objectclass=nisObject)" under
"ou=auto.podraid2,ou=autofs,dc=podzinger,dc=local"
Oct 6 17:48:40 dev-worker-05 automount[960]: lookup(ldap): query succeeded, no
matches for (objectclass=nisObject)
Oct 6 17:48:40 dev-worker-05 automount[960]: lookup(ldap): searching for
"(objectclass=automount)" under
"ou=auto.podraid2,ou=autofs,dc=podzinger,dc=local"
Oct 6 17:48:40 dev-worker-05 automount[960]: lookup(ldap): examining entries
Oct 6 17:48:40 dev-worker-05 automount[960]: lookup(ldap): done updating map
Oct 6 17:48:40 dev-worker-05 automount[960]: ghosting enabled
######################################################################
# cat /mnt-via-file/u10/test
Contents of test.
######################################################################
Oct 6 17:48:59 dev-worker-05 automount[901]: handle_packet: type = 0
Oct 6 17:48:59 dev-worker-05 automount[901]: handle_packet_missing: token 145,
name u10
Oct 6 17:48:59 dev-worker-05 automount[901]: attempting to mount entry
/mnt-via-file/u10
Oct 6 17:48:59 dev-worker-05 automount[1775]: checking for modifications to
map /etc/auto.mnt
Oct 6 17:48:59 dev-worker-05 automount[1775]: file map /etc/auto.mnt mtime
1191704252, last 1191704252
Oct 6 17:48:59 dev-worker-05 automount[1775]: map_modified: no changes
Oct 6 17:48:59 dev-worker-05 automount[1775]: lookup(file): u10 ->
podraid2.podzinger.local:/export/&
Oct 6 17:48:59 dev-worker-05 automount[1775]: parse(sun): expanded entry:
podraid2.podzinger.local:/export/u10
Oct 6 17:48:59 dev-worker-05 automount[1775]: parse(sun): gathered options:
rw,hard,intr
Oct 6 17:48:59 dev-worker-05 automount[1775]: parse(sun):
dequote("podraid2.podzinger.local:/export/u10") ->
podraid2.podzinger.local:/export/u10
Oct 6 17:48:59 dev-worker-05 automount[1775]: parse(sun): core of entry:
options=rw,hard,intr, loc=podraid2.podzinger.local:/export/u10
Oct 6 17:48:59 dev-worker-05 automount[1775]: parse(sun): mounting root
/mnt-via-file, mountpoint u10, what podraid2.podzinger.local:/export/u10,
fstype nfs, options rw,hard,intr
Oct 6 17:48:59 dev-worker-05 automount[1775]: mount(nfs): root=/mnt-via-file
name=u10 what=podraid2.podzinger.local:/export/u10, fstype=nfs,
options=rw,hard,intr
Oct 6 17:48:59 dev-worker-05 automount[1775]: mount(nfs): nfs
options="rw,hard,intr", nosymlink=0
Oct 6 17:48:59 dev-worker-05 automount[1775]: mount(nfs): is_bad_host:
podraid2.podzinger.local:/export/u10
Oct 6 17:48:59 dev-worker-05 automount[1775]: mount(nfs): is_local_mount:
podraid2.podzinger.local:/export/u10
Oct 6 17:48:59 dev-worker-05 automount[1775]: mount(nfs): from
podraid2.podzinger.local:/export/u10 elected
podraid2.podzinger.local:/export/u10
Oct 6 17:48:59 dev-worker-05 automount[1775]: mount(nfs): calling mkdir_path
/mnt-via-file/u10
Oct 6 17:48:59 dev-worker-05 automount[1775]: mount(nfs): calling mount -t nfs
-s -o rw,hard,intr podraid2.podzinger.local:/export/u10 /mnt-via-file/u10
Oct 6 17:49:00 dev-worker-05 automount[1775]: mount(nfs): mounted
podraid2.podzinger.local:/export/u10 on /mnt-via-file/u10
Oct 6 17:49:00 dev-worker-05 automount[901]: handle_child: got pid 1775, sig 0
(0), stat 0
Oct 6 17:49:00 dev-worker-05 automount[901]: sig_child: found pending iop pid
1775: signalled 0 (sig 0), exit status 0
Oct 6 17:49:00 dev-worker-05 automount[901]: send_ready: token=145
######################################################################
# umount /mnt-via-file/u10
# cat /mnt/via-file/u10/test
Contents of test.
######################################################################
Oct 6 17:49:37 dev-worker-05 automount[901]: handle_packet: type = 0
Oct 6 17:49:37 dev-worker-05 automount[901]: handle_packet_missing: token 146,
name u10
Oct 6 17:49:37 dev-worker-05 automount[901]: attempting to mount entry
/mnt-via-file/u10
Oct 6 17:49:37 dev-worker-05 automount[1785]: checking for modifications to
map /etc/auto.mnt
Oct 6 17:49:37 dev-worker-05 automount[1785]: file map /etc/auto.mnt mtime
1191704252, last 1191704252
Oct 6 17:49:37 dev-worker-05 automount[1785]: map_modified: no changes
Oct 6 17:49:37 dev-worker-05 automount[1785]: lookup(file): u10 ->
podraid2.podzinger.local:/export/&
Oct 6 17:49:37 dev-worker-05 automount[1785]: parse(sun): expanded entry:
podraid2.podzinger.local:/export/u10
Oct 6 17:49:37 dev-worker-05 automount[1785]: parse(sun): gathered options:
rw,hard,intr
Oct 6 17:49:37 dev-worker-05 automount[1785]: parse(sun):
dequote("podraid2.podzinger.local:/export/u10") ->
podraid2.podzinger.local:/export/u10
Oct 6 17:49:37 dev-worker-05 automount[1785]: parse(sun): core of entry:
options=rw,hard,intr, loc=podraid2.podzinger.local:/export/u10
Oct 6 17:49:37 dev-worker-05 automount[1785]: parse(sun): mounting root
/mnt-via-file, mountpoint u10, what podraid2.podzinger.local:/export/u10,
fstype nfs, options rw,hard,intr
Oct 6 17:49:37 dev-worker-05 automount[1785]: mount(nfs): root=/mnt-via-file
name=u10 what=podraid2.podzinger.local:/export/u10, fstype=nfs,
options=rw,hard,intr
Oct 6 17:49:37 dev-worker-05 automount[1785]: mount(nfs): nfs
options="rw,hard,intr", nosymlink=0
Oct 6 17:49:37 dev-worker-05 automount[1785]: mount(nfs): is_bad_host:
podraid2.podzinger.local:/export/u10
Oct 6 17:49:37 dev-worker-05 automount[1785]: mount(nfs): is_local_mount:
podraid2.podzinger.local:/export/u10
Oct 6 17:49:37 dev-worker-05 automount[1785]: mount(nfs): from
podraid2.podzinger.local:/export/u10 elected
podraid2.podzinger.local:/export/u10
Oct 6 17:49:37 dev-worker-05 automount[1785]: mount(nfs): calling mkdir_path
/mnt-via-file/u10
Oct 6 17:49:37 dev-worker-05 automount[1785]: mount(nfs): calling mount -t nfs
-s -o rw,hard,intr podraid2.podzinger.local:/export/u10 /mnt-via-file/u10
Oct 6 17:49:37 dev-worker-05 automount[1785]: mount(nfs): mounted
podraid2.podzinger.local:/export/u10 on /mnt-via-file/u10
Oct 6 17:49:37 dev-worker-05 automount[901]: handle_child: got pid 1785, sig 0
(0), stat 0
Oct 6 17:49:37 dev-worker-05 automount[901]: sig_child: found pending iop pid
1785: signalled 0 (sig 0), exit status 0
Oct 6 17:49:37 dev-worker-05 automount[901]: send_ready: token=146
######################################################################
# umount /mnt-via-file/u10/test
# cat /mnt-via-ldap/u10/test
Contents of test.
######################################################################
Oct 6 17:50:20 dev-worker-05 automount[960]: handle_packet: type = 0
Oct 6 17:50:20 dev-worker-05 automount[960]: handle_packet_missing: token 147,
name u10
Oct 6 17:50:20 dev-worker-05 automount[960]: attempting to mount entry
/mnt-via-ldap/u10
Oct 6 17:50:20 dev-worker-05 automount[1793]: lookup(ldap): searching for
"(&(objectclass=automount)(cn=u10))" under
"ou=auto.podraid2,ou=autofs,dc=podzinger,dc=local"
Oct 6 17:50:20 dev-worker-05 automount[1793]: lookup(ldap): getting first
entry for cn="u10"
Oct 6 17:50:20 dev-worker-05 automount[1793]: lookup(ldap): got answer, but no
first entry for (&(objectclass=automount)(cn=u10))
Oct 6 17:50:20 dev-worker-05 automount[1793]: lookup_one with schema
cn,automount,automountInformation returns 8
Oct 6 17:50:20 dev-worker-05 automount[1793]: lookup(ldap): searching for
"(&(objectclass=automount)(cn=/))" under
"ou=auto.podraid2,ou=autofs,dc=podzinger,dc=local"
Oct 6 17:50:20 dev-worker-05 automount[1793]: lookup(ldap): getting first
entry for cn="/"
Oct 6 17:50:20 dev-worker-05 automount[1793]: lookup(ldap): got answer, but no
first entry for (&(objectclass=automount)(cn=/))
Oct 6 17:50:20 dev-worker-05 automount[1793]: lookup(ldap): u10 ->
podraid2.podzinger.local:/export/&
Oct 6 17:50:20 dev-worker-05 automount[1793]: parse(sun): expanded entry:
podraid2.podzinger.local:/export/u10
Oct 6 17:50:20 dev-worker-05 automount[1793]: parse(sun): gathered options:
rw,hard,intr
Oct 6 17:50:20 dev-worker-05 automount[1793]: parse(sun):
dequote("podraid2.podzinger.local:/export/u10") ->
podraid2.podzinger.local:/export/u10
Oct 6 17:50:20 dev-worker-05 automount[1793]: parse(sun): core of entry:
options=rw,hard,intr, loc=podraid2.podzinger.local:/export/u10
Oct 6 17:50:20 dev-worker-05 automount[1793]: parse(sun): mounting root
/mnt-via-ldap, mountpoint u10, what podraid2.podzinger.local:/export/u10,
fstype nfs, options rw,hard,intr
Oct 6 17:50:20 dev-worker-05 automount[1793]: mount(nfs): root=/mnt-via-ldap
name=u10 what=podraid2.podzinger.local:/export/u10, fstype=nfs,
options=rw,hard,intr
Oct 6 17:50:20 dev-worker-05 automount[1793]: mount(nfs): nfs
options="rw,hard,intr", nosymlink=0
Oct 6 17:50:20 dev-worker-05 automount[1793]: mount(nfs): is_bad_host:
podraid2.podzinger.local:/export/u10
Oct 6 17:50:20 dev-worker-05 automount[1793]: mount(nfs): is_local_mount:
podraid2.podzinger.local:/export/u10
Oct 6 17:50:20 dev-worker-05 automount[1793]: mount(nfs): from
podraid2.podzinger.local:/export/u10 elected
podraid2.podzinger.local:/export/u10
Oct 6 17:50:20 dev-worker-05 automount[1793]: mount(nfs): calling mkdir_path
/mnt-via-ldap/u10
Oct 6 17:50:20 dev-worker-05 automount[1793]: mount(nfs): calling mount -t nfs
-s -o rw,hard,intr podraid2.podzinger.local:/export/u10 /mnt-via-ldap/u10
Oct 6 17:50:20 dev-worker-05 automount[1793]: mount(nfs): mounted
podraid2.podzinger.local:/export/u10 on /mnt-via-ldap/u10
Oct 6 17:50:20 dev-worker-05 automount[960]: handle_child: got pid 1793, sig 0
(0), stat 0
Oct 6 17:50:20 dev-worker-05 automount[960]: sig_child: found pending iop pid
1793: signalled 0 (sig 0), exit status 0
Oct 6 17:50:20 dev-worker-05 automount[960]: send_ready: token=147
######################################################################
# umount /mnt-via-ldap/u10
# cat /mnt-via-ldap/u10/test
cat: /mnt-via-ldap/u10/test: No such file or directory
Note that the output below actually appears to my eye to show up
in the log (tail -f) AFTER cat has printed "No such file or directory"
######################################################################
Oct 6 17:50:31 dev-worker-05 automount[960]: handle_packet: type = 0
Oct 6 17:50:31 dev-worker-05 automount[960]: handle_packet_missing: token 148,
name u10
Oct 6 17:50:31 dev-worker-05 automount[960]: attempting to mount entry
/mnt-via-ldap/u10
Oct 6 17:50:31 dev-worker-05 automount[1801]: lookup(ldap): searching for
"(&(objectclass=automount)(cn=u10))" under
"ou=auto.podraid2,ou=autofs,dc=podzinger,dc=local"
Oct 6 17:50:31 dev-worker-05 automount[1801]: lookup(ldap): getting first
entry for cn="u10"
Oct 6 17:50:31 dev-worker-05 automount[1801]: lookup(ldap): got answer, but no
first entry for (&(objectclass=automount)(cn=u10))
Oct 6 17:50:31 dev-worker-05 automount[1801]: lookup_one with schema
cn,automount,automountInformation returns 8
Oct 6 17:50:31 dev-worker-05 automount[1801]: lookup(ldap): searching for
"(&(objectclass=automount)(cn=/))" under
"ou=auto.podraid2,ou=autofs,dc=podzinger,dc=local"
Oct 6 17:50:31 dev-worker-05 automount[1801]: lookup(ldap): getting first
entry for cn="/"
Oct 6 17:50:31 dev-worker-05 automount[1801]: lookup(ldap): got answer, but no
first entry for (&(objectclass=automount)(cn=/))
Oct 6 17:50:31 dev-worker-05 automount[1801]: lookup(ldap): u10 ->
podraid2.podzinger.local:/export/&
Oct 6 17:50:31 dev-worker-05 automount[1801]: parse(sun): expanded entry:
podraid2.podzinger.local:/export/u10
Oct 6 17:50:31 dev-worker-05 automount[1801]: parse(sun): gathered options:
rw,hard,intr
Oct 6 17:50:31 dev-worker-05 automount[1801]: parse(sun):
dequote("podraid2.podzinger.local:/export/u10") ->
podraid2.podzinger.local:/export/u10
Oct 6 17:50:31 dev-worker-05 automount[1801]: parse(sun): core of entry:
options=rw,hard,intr, loc=podraid2.podzinger.local:/export/u10
Oct 6 17:50:31 dev-worker-05 automount[1801]: parse(sun): mounting root
/mnt-via-ldap, mountpoint u10, what podraid2.podzinger.local:/export/u10,
fstype nfs, options rw,hard,intr
Oct 6 17:50:31 dev-worker-05 automount[1801]: mount(nfs): root=/mnt-via-ldap
name=u10 what=podraid2.podzinger.local:/export/u10, fstype=nfs,
options=rw,hard,intr
Oct 6 17:50:31 dev-worker-05 automount[1801]: mount(nfs): nfs
options="rw,hard,intr", nosymlink=0
Oct 6 17:50:31 dev-worker-05 automount[1801]: mount(nfs): is_bad_host:
podraid2.podzinger.local:/export/u10
Oct 6 17:50:31 dev-worker-05 automount[1801]: mount(nfs): is_local_mount:
podraid2.podzinger.local:/export/u10
Oct 6 17:50:31 dev-worker-05 automount[1801]: mount(nfs): from
podraid2.podzinger.local:/export/u10 elected
podraid2.podzinger.local:/export/u10
Oct 6 17:50:31 dev-worker-05 automount[1801]: mount(nfs): calling mkdir_path
/mnt-via-ldap/u10
Oct 6 17:50:31 dev-worker-05 automount[1801]: mount(nfs): calling mount -t nfs
-s -o rw,hard,intr podraid2.podzinger.local:/export/u10 /mnt-via-ldap/u10
Oct 6 17:50:32 dev-worker-05 automount[1801]: mount(nfs): mounted
podraid2.podzinger.local:/export/u10 on /mnt-via-ldap/u10
Oct 6 17:50:32 dev-worker-05 automount[960]: handle_child: got pid 1801, sig 0
(0), stat 0
Oct 6 17:50:32 dev-worker-05 automount[960]: sig_child: found pending iop pid
1801: signalled 0 (sig 0), exit status 0
Oct 6 17:50:32 dev-worker-05 automount[960]: send_ready: token=148
Oct 6 17:50:32 dev-worker-05 automount[960]: handle_packet: type = 0
Oct 6 17:50:32 dev-worker-05 automount[960]: handle_packet_missing: token 149,
name u10/test
Oct 6 17:50:32 dev-worker-05 automount[960]: send_ready: token=149
######################################################################
# cat /mnt-via-ldap/u10/test
Contents of test.
######################################################################
_______________________________________________
autofs mailing list
[email protected]
http://linux.kernel.org/mailman/listinfo/autofs
