Autofs bug

Bradley Baetz (bbaetz@uuscss.cs.usyd.edu.au)
Thu, 23 Apr 1998 17:36:26 +1000


Yesterday my autofs system blew up:

Apr 22 18:17:29 onion automount[2405]: attempting to mount entry
/mnt/dos
Apr 22 18:17:33 onion automount[2405]: attempting to mount entry
/mnt/dos
Apr 22 18:17:33 onion automount[2657]: expired /mnt/dos
Apr 22 18:18:10 onion automount[2405]: attempting to mount entry
/mnt/dos
Apr 22 18:18:10 onion automount[2662]: >> mount: /dev/hda1 already
mounted or /mnt/dos busy
Apr 22 18:18:10 onion kernel: autofs warning: lookup failure on existing
dentry, status = -2, name = dos
Apr 22 18:18:10 onion automount[2662]: >> mount: according to mtab,
/dev/hda1 is already mounted on /mnt/dos
Apr 22 18:18:10 onion automount[2662]: mount(generic): failed to mount
/dev/hda1 (type vfat) on /mnt/dos
Apr 22 18:18:10 onion kernel: autofs warning: lookup failure on existing
dentry, status = -2, name = dos
Apr 22 18:18:10 onion automount[2405]: attempting to mount entry
/mnt/dos
Apr 22 18:18:10 onion automount[2664]: >> mount: /dev/hda1 already
mounted or /mnt/dos busy
Apr 22 18:18:10 onion automount[2664]: >> mount: according to mtab,
/dev/hda1 is already mounted on /mnt/dos
Apr 22 18:18:10 onion automount[2664]: mount(generic): failed to mount
/dev/hda1 (type vfat) on /mnt/dos

These kept repeating everytime I tried to access /mnt/dos until I
restarted the system. Trying to stop the automounter through the rc
scripts failed, saying that /mnt/dos was mounted.
However, noticing the 2nd mount attempt happened _before_ the expiration
of the first, I logged the daemon debugging messages, and tried to get
it to repeat:

~# cat /mnt/dos/test; usleep 3600000; cat /mnt/dos/test

Apr 23 10:40:20 onion automount[516]: attempting to mount entry /mnt/dos
Apr 23 10:40:20 onion automount[565]: lookup(file): looking up dos
Apr 23 10:40:20 onion automount[565]: lookup(file): dos ->
-fstype=vfat,umask=000^I:/dev/hda1
Apr 23 10:40:20 onion automount[565]: expanded entry:
-fstype=vfat,umask=000^I:/dev/hda1
Apr 23 10:40:20 onion automount[565]: parse(sun): gathered options:
fstype=vfat,umask=000
Apr 23 10:40:20 onion automount[565]: parse(sun): core of entry:
/dev/hda1
Apr 23 10:40:20 onion automount[565]: do_mount /dev/hda1 /mnt/dos type
vfat options umask=000 using module generic
Apr 23 10:40:20 onion automount[565]: mount(generic): calling mkdir
/mnt/dos
Apr 23 10:40:20 onion automount[565]: mount(generic): calling mount -t
vfat -s -o umask=000 /dev/hda1 /mnt/dos
Apr 23 10:40:21 onion automount[565]: mount(generic): mounted /dev/hda1
type vfat on /mnt/dos
Apr 23 10:40:24 onion automount[568]: running expiration on path /mnt
Apr 23 10:40:24 onion automount[516]: attempting to mount entry /mnt/dos
Apr 23 10:40:24 onion automount[571]: lookup(file): looking up dos
Apr 23 10:40:24 onion automount[571]: lookup(file): dos ->
-fstype=vfat,umask=000^I:/dev/hda1
Apr 23 10:40:24 onion automount[571]: expanded entry:
-fstype=vfat,umask=000^I:/dev/hda1
Apr 23 10:40:24 onion automount[571]: parse(sun): gathered options:
fstype=vfat,umask=000
Apr 23 10:40:24 onion automount[571]: parse(sun): core of entry:
/dev/hda1
Apr 23 10:40:24 onion automount[571]: do_mount /dev/hda1 /mnt/dos type
vfat options umask=000 using module generic
Apr 23 10:40:24 onion automount[571]: mount(generic): calling mkdir
/mnt/dos
Apr 23 10:40:24 onion automount[571]: mount(generic): calling mount -t
vfat -s -o umask=000 /dev/hda1 /mnt/dos
Apr 23 10:40:24 onion automount[568]: expired /mnt/dos
Apr 23 10:40:24 onion automount[571]: >> mount: mount point /mnt/dos
does not exist
Apr 23 10:40:24 onion automount[571]: mount(generic): failed to mount
/dev/hda1 (type vfat) on /mnt/dos
Apr 23 10:40:24 onion automount[516]: attempting to mount entry /mnt/dos
Apr 23 10:40:24 onion automount[573]: lookup(file): looking up dos
Apr 23 10:40:24 onion automount[573]: lookup(file): dos ->
-fstype=vfat,umask=000^I:/dev/hda1
Apr 23 10:40:24 onion automount[573]: expanded entry:
-fstype=vfat,umask=000^I:/dev/hda1
Apr 23 10:40:24 onion automount[573]: parse(sun): gathered options:
fstype=vfat,umask=000
Apr 23 10:40:24 onion automount[573]: parse(sun): core of entry:
/dev/hda1
Apr 23 10:40:24 onion automount[573]: do_mount /dev/hda1 /mnt/dos type
vfat options umask=000 using module generic
Apr 23 10:40:24 onion automount[573]: mount(generic): calling mkdir
/mnt/dos

The automount process, pid 573 hung in a D state, until I pressed
Ctrl-C, when it continued normally, but without printing the contests of
the test file.

Apr 23 10:44:48 onion automount[573]: mount(generic): calling mount -t
vfat -s -o umask=000 /dev/hda1 /mnt/dos
Apr 23 10:44:48 onion automount[573]: mount(generic): mounted /dev/hda1
type vfat on /mnt/dos
Apr 23 10:44:51 onion automount[608]: running expiration on path /mnt
Apr 23 10:44:51 onion automount[608]: expired /mnt/dos

~# cd /mnt/dos

Apr 23 10:45:11 onion automount[516]: attempting to mount entry /mnt/dos
Apr 23 10:45:11 onion automount[610]: lookup(file): looking up dos
Apr 23 10:45:11 onion automount[610]: lookup(file): dos ->
-fstype=vfat,umask=000^I:/dev/hda1
Apr 23 10:45:11 onion automount[610]: expanded entry:
-fstype=vfat,umask=000^I:/dev/hda1
Apr 23 10:45:11 onion automount[610]: parse(sun): gathered options:
fstype=vfat,umask=000
Apr 23 10:45:11 onion automount[610]: parse(sun): core of entry:
/dev/hda1
Apr 23 10:45:11 onion automount[610]: do_mount /dev/hda1 /mnt/dos type
vfat options umask=000 using module generic
Apr 23 10:45:11 onion automount[610]: mount(generic): calling mkdir
/mnt/dos
Apr 23 10:45:11 onion automount[610]: mount(generic): calling mount -t
vfat -s -o umask=000 /dev/hda1 /mnt/dos
Apr 23 10:45:12 onion automount[610]: mount(generic): mounted /dev/hda1
type vfat on /mnt/dos
Apr 23 10:45:15 onion automount[613]: running expiration on path /mnt
Apr 23 10:45:15 onion automount[613]: >> umount: /mnt/dos: device is
busy
Apr 23 10:45:18 onion automount[615]: running expiration on path /mnt
Apr 23 10:45:18 onion automount[615]: expired /mnt/dos

The amount for the udelay doesn't appear to be constant - I had to
adjust it by looking at the logs and reducing/increasing the value so
that they overlapped to get this to happen. As well, I'd tried this
value before, and nothing happened then. This is on an unloaded system.
Of interest is the fact that the automount daemon has running
expiration, attempting mount, _then_ expired /mnt/dos. It shouldn't be
doing this, should it? This time, I could continue automounting /mnt/dos
as normal.

However, looking through my logs, similar events (ie mounting before
expiry) have happened before, sometimes with a corresponding loss in
data in my rc5 buffers, which are symlinked from /usr/local/rc5des to
/mnt/dos/rc5des, and, according to my rc5 logs, state that, from about
20 blocks, they now have none. This has been happeneing for a while.

Automount version was 3.1.1, and kernel version was 2.1.95 for the
yesterday's results, and 2.1.97 for todays. Timeout in /etc/auto.master
was set to 3 seconds.

Hope this helps,

Bradley

PS I am only subscribed to the digest, so please mail me direct if you
want further information. Thanks

-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.rutgers.edu