tests: make TestTypeChange robust against outside interference

I have suddenly seen TestTypeChange hang forever, waiting for the
FORGET that never arrives. The first concern was that the assumption
that the FORGET always follows the delete was wrong. Checking the
kernel source code, the FORGET should really, actually always follow
the delete.

Looking more closely on the debug trace showed this:

        LOOKUP i1 [".Trash-1026"] 12b
             OK, {i1234 g0 tE=0s tA=0s {M0100644 SZ=0 L=0 0:0 B0*4096 i0:1234 A 0.000000 M 0.000000 C 0.000000}}

This is the desktop environment looking for the trash folder.
And because the test is stupid, it returned the same dummy
inode i1234. This means the kernel had one extra reference
to this inode and, of course, did not send a FORGET when
"file" was deleted.

I made testTypeChangeIno only react to expected file names
now, and added a log output should we wait more than ~5
seconds for the FORGET. The log message then repeats indefinitely
every 5 seconds.

        ~/go/src/github.com/hanwen/go-fuse/fs$ go test -v -run TestTypeChange
        === RUN   TestTypeChange
        20:50:18.491584 rx 2: INIT i0 {7.31 Ra 0x20000 CACHE_SYMLINKS,POSIX_LOCKS,SPLICE_MOVE,SPLICE_READ,READDIRPLUS,READDIRPLUS_AUTO,PARALLEL_DIROPS,ABORT_ERROR,EXPLICIT_INVAL_DATA,ASYNC_READ,EXPORT_SUPPORT,DONT_MASK,NO_OPENDIR_SUPPORT,SPLICE_WRITE,FLOCK_LOCKS,AUTO_INVAL_DATA,HANDLE_KILLPRIV,MAX_PAGES,POSIX_ACL,ATOMIC_O_TRUNC,BIG_WRITES,IOCTL_DIR,ASYNC_DIO,WRITEBACK_CACHE,NO_OPEN_SUPPORT}
        20:50:18.491728 tx 2:     OK, {7.28 Ra 0x20000 NO_OPEN_SUPPORT,BIG_WRITES,PARALLEL_DIROPS,READDIRPLUS,ASYNC_READ,AUTO_INVAL_DATA 0/0 Wr 0x10000 Tg 0x0}
        20:50:18.491857 rx 4: ACCESS i1 {u=1026 g=1026 r}
        20:50:18.491873 tx 4:     OK
        20:50:18.492028 rx 6: LOOKUP i1 [".go-fuse-epoll-hack"] 20b
        20:50:18.492110 tx 6:     2=no such file or directory, {i0 g0 tE=0s tA=0s {M00 SZ=0 L=0 0:0 B0*0 i0:0 A 0.000000 M 0.000000 C 0.000000}}
        20:50:18.492147 rx 8: CREATE i1 {0100100 [TRUNC,WRONLY,CREAT,0x8000] (00)} [".go-fuse-epoll-hack"] 20b
        20:50:18.492207 tx 8:     OK, {i18446744073709551615 g0 {M0100644 SZ=0 L=1 0:0 B0*0 i0:18446744073709551615 A 0.000000 M 0.000000 C 0.000000} &{18446744073709551615 0 0}}
        20:50:18.492291 rx 10: LOOKUP i1 [".Trash"] 7b
        20:50:18.492340 tx 10:     OK, {i1234 g0 tE=0s tA=0s {M0100644 SZ=0 L=0 0:0 B0*4096 i0:1234 A 0.000000 M 0.000000 C 0.000000}}
        20:50:18.492354 rx 12: POLL i18446744073709551615
        20:50:18.492359 tx 12:     38=function not implemented
        20:50:18.492370 rx 14: LOOKUP i1 [".go-fuse-epoll-hack"] 20b
        20:50:18.492378 tx 14:     2=no such file or directory, {i0 g0 tE=0s tA=0s {M00 SZ=0 L=0 0:0 B0*0 i0:0 A 0.000000 M 0.000000 C 0.000000}}
        20:50:18.492389 rx 16: GETATTR i1234 {Fh 0}
        20:50:18.492398 tx 16:     OK, {tA=0s {M0100644 SZ=0 L=0 0:0 B0*4096 i0:1234 A 0.000000 M 0.000000 C 0.000000}}
        20:50:18.492412 rx 18: FLUSH i18446744073709551615 {Fh 18446744073709551615}
        20:50:18.492417 tx 18:     5=input/output error
        20:50:18.492427 rx 20: LOOKUP i1 [".go-fuse-epoll-hack"] 20b
        20:50:18.492435 tx 20:     2=no such file or directory, {i0 g0 tE=0s tA=0s {M00 SZ=0 L=0 0:0 B0*0 i0:0 A 0.000000 M 0.000000 C 0.000000}}
        20:50:18.492450 rx 22: RELEASE i18446744073709551615 {Fh 18446744073709551615 WRONLY,0x8000  L0}
        20:50:18.492456 tx 22:     5=input/output error
        20:50:18.492469 rx 24: LOOKUP i1 ["file"] 5b
        20:50:18.492477 tx 24:     OK, {i1234 g0 tE=0s tA=0s {M0100644 SZ=0 L=0 0:0 B0*4096 i0:1234 A 0.000000 M 0.000000 C 0.000000}}
        20:50:18.492489 rx 26: LOOKUP i1 [".Trash-1026"] 12b
        20:50:18.492497 tx 26:     OK, {i1234 g0 tE=0s tA=0s {M0100644 SZ=0 L=0 0:0 B0*4096 i0:1234 A 0.000000 M 0.000000 C 0.000000}}
        20:50:18.492506 rx 28: GETATTR i1234 {Fh 0}
        20:50:18.492513 tx 28:     OK, {tA=0s {M0100644 SZ=0 L=0 0:0 B0*4096 i0:1234 A 0.000000 M 0.000000 C 0.000000}}
        20:50:18.492521 rx 30: GETATTR i1234 {Fh 0}
        20:50:18.492528 tx 30:     OK, {tA=0s {M0100644 SZ=0 L=0 0:0 B0*4096 i0:1234 A 0.000000 M 0.000000 C 0.000000}}
        20:50:18.492537 rx 32: LOOKUP i1 ["file"] 5b
        20:50:18.492545 tx 32:     OK, {i1234 g0 tE=0s tA=0s {M0100644 SZ=0 L=0 0:0 B0*4096 i0:1234 A 0.000000 M 0.000000 C 0.000000}}
        20:50:18.492555 rx 34: FORGET i18446744073709551615 {Nlookup=1}
        20:50:18.492575 rx 36: UNLINK i1 ["file"] 5b
        20:50:18.492588 tx 36:     OK
        20:50:18.492621 rx 38: LOOKUP i1 ["dir"] 4b
        [hangs here]

Change-Id: Ibee48faf09c5a8993dfc7bb75251551f699cd63e

fs/bridge.go

@@ -106,7 +106,8 @@ func (b *rawBridge) newInodeUnlocked(ops InodeEmbedder, id StableAttr, persisten
 	// simultaneously.  The matching StableAttrs ensure that we return the
 	// same node.
 	var t time.Duration
-	for {
+	t0 := time.Now()
+	for i := 1; true; i++ {
 		old := b.nodes[id.Ino]
 		if old == nil {
 			break
@@ -121,6 +122,9 @@ func (b *rawBridge) newInodeUnlocked(ops InodeEmbedder, id StableAttr, persisten
 				id.Mode, t)
 		}
 		t = expSleep(t)
+		if i%5000 == 0 {
+			log.Printf("blocked for %.0f seconds waiting for FORGET on i%d", time.Since(t0).Seconds(), id.Ino)
+		}
 		b.mu.Lock()
 	}
 

fs/bridge_test.go

@@ -107,12 +107,19 @@ type testTypeChangeIno struct {
 	Inode
 }
 
-// Lookup function for TestTypeChange: if name == "dir", returns a node of
-// type dir, otherwise of type file.
+// Lookup function for TestTypeChange:
+// If name == "dir", returns a node of type dir,
+// if name == "file" of type file,
+// otherwise ENOENT.
 func (fn *testTypeChangeIno) Lookup(ctx context.Context, name string, out *fuse.EntryOut) (*Inode, syscall.Errno) {
-	mode := uint32(fuse.S_IFREG)
-	if name == "dir" {
-		mode = fuse.S_IFDIR
+	var mode uint32
+	switch name {
+	case "file":
+		mode = syscall.S_IFREG
+	case "dir":
+		mode = syscall.S_IFDIR
+	default:
+		return nil, syscall.ENOENT
 	}
 	stable := StableAttr{
 		Mode: mode,