Attachment 219821 Details for Bug 323181 – debug log from the automounter

debug log from the automounter

attachment (text/plain), 18.29 KB, created by Jeff Moyer on 2007-10-08 15:22:30 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Jeff Moyer

Created: 2007-10-08 15:22:30 UTC

Size: 18.29 KB

patch

obsolete

>BABYL OPTIONS: -*- rmail -*-
>Version: 5
>Labels:
>Note:   This is the header of an rmail file.
>Note:   If you are seeing it in rmail,
>Note:    it means the file has no messages in it.
>
>1,,
>Return-Path: <autofs-bounces@linux.kernel.org>
>Received: from mail.boston.redhat.com ([unix socket])
>	 by mail.boston.redhat.com (Cyrus v2.2.12-Invoca-RPM-2.2.12-8.1.RHEL4) with LMTPA;
>	 Sat, 06 Oct 2007 19:12:10 -0400
>X-Sieve: CMU Sieve 2.2
>Received: from int-mx1.corp.redhat.com (int-mx1.corp.redhat.com [172.16.52.254])
>	by mail.boston.redhat.com (8.13.1/8.13.1) with ESMTP id l96NCAiC029489;
>	Sat, 6 Oct 2007 19:12:10 -0400
>Received: from mx3.redhat.com (mx3.redhat.com [172.16.48.32])
>	by int-mx1.corp.redhat.com (8.13.1/8.13.1) with ESMTP id l96NC9RZ014970;
>	Sat, 6 Oct 2007 19:12:09 -0400
>Received: from hera.kernel.org (IDENT:U2FsdGVkX1/kXAcIEt2kYzNHfFL5rX/itB4ik14GhV4@hera.kernel.org [140.211.167.34])
>	by mx3.redhat.com (8.13.1/8.13.1) with ESMTP id l96NBx3B024872;
>	Sat, 6 Oct 2007 19:12:00 -0400
>Received: from hera.kernel.org (IDENT:U2FsdGVkX18xvFqISzO5ljQxrBFRYQXaa5N+9aZDtBg@localhost [127.0.0.1])
>	by hera.kernel.org (8.13.8/8.13.8) with ESMTP id l96N4ArJ001892;
>	Sat, 6 Oct 2007 23:04:38 GMT
>Received: from iss04.interliant.com (iss04.interliant.com [207.113.241.148])
>	by hera.kernel.org (8.13.8/8.13.8) with ESMTP id l96N406E001712
>	for <autofs@kernel.org>; Sat, 6 Oct 2007 23:04:01 GMT
>Received: from EX-009.mail.navisite.com (ex-009.interliant.com
>	[207.113.240.184])
>	by iss04.interliant.com (8.10.2/8.10.2) with ESMTP id l96N3qh15927
>	for <autofs@kernel.org>; Sat, 6 Oct 2007 18:03:54 -0500 (CDT)
>Received: from [192.168.0.101] ([71.174.225.192]) by EX-009.mail.navisite.com
>	over TLS secured channel with Microsoft SMTPSVC(6.0.3790.1830); 
>	Sat, 6 Oct 2007 18:03:48 -0500
>Message-ID: <47081453.7000709@everyzing.com>
>Date: Sat, 06 Oct 2007 19:03:47 -0400
>From: Dan Halbert <halbert@everyzing.com>
>User-Agent: Thunderbird 2.0.0.6 (Windows/20070728)
>MIME-Version: 1.0
>To: autofs@kernel.org
>References: <4706A926.8090503@everyzing.com>
>	<1191646125.3060.7.camel@raven.themaw.net>
>In-Reply-To: <1191646125.3060.7.camel@raven.themaw.net>
>X-OriginalArrivalTime: 06 Oct 2007 23:03:48.0919 (UTC)
>	FILETIME=[279E1C70:01C8086D]
>X-Virus-Scanned: ClamAV 0.88.7/4486/Sat Oct 6 21:19:34 2007 on hera.kernel.org
>X-Virus-Status: Clean
>X-Spam-Status: No, score=-2.4 required=5.0 tests=AWL,BAYES_00
>	autolearn=unavailable version=3.2.3
>X-Spam-Checker-Version: SpamAssassin 3.2.3 (2007-08-08) on hera.kernel.org
>Subject: Re: [autofs] ENOENT on first reference to an automounted file
>X-BeenThere: autofs@linux.kernel.org
>X-Mailman-Version: 2.1.9
>Precedence: list
>List-Id: Discussion list for the autofs automounter for Linux
>	<autofs.linux.kernel.org>
>List-Unsubscribe: <http://linux.kernel.org/mailman/listinfo/autofs>,
>	<mailto:autofs-request@linux.kernel.org?subject=unsubscribe>
>List-Archive: <http://linux.kernel.org/pipermail/autofs>
>List-Post: <mailto:autofs@linux.kernel.org>
>List-Help: <mailto:autofs-request@linux.kernel.org?subject=help>
>List-Subscribe: <http://linux.kernel.org/mailman/listinfo/autofs>,
>	<mailto:autofs-request@linux.kernel.org?subject=subscribe>
>Content-Type: text/plain; charset="us-ascii"
>Content-Transfer-Encoding: 7bit
>Sender: autofs-bounces@linux.kernel.org
>Errors-To: autofs-bounces@linux.kernel.org
>X-RedHat-Spam-Score: 0 
>X-Scanned-By: MIMEDefang 2.58 on 172.16.48.32
>
>*** EOOH ***
>######################################################################
># 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.
>######################################################################
>

Actions: View

Attachments on bug 323181: 219821