Issues when unmounting on linux/ darwin #512

marius-enlock · 2024-04-25T04:24:34Z

Hi,

On linux I found the need to call fusermount -uz mountpoint, in the unmount command;

I get the following panic:

Exit
Line: 2024/04/25 07:16:07 unmount: executing ["/usr/bin/fusermount3" "-uz" "/home/marius/playground/test_mount"]
Line: 2024/04/25 07:16:07 received ENODEV (unmount request), thread exiting
Line: 2024/04/25 07:16:07 received ENODEV (unmount request), thread exiting
Line: 2024/04/25 07:16:07 received ENODEV (unmount request), thread exiting
Line: 2024/04/25 07:16:07 received ENODEV (unmount request), thread exiting
Line: 2024/04/25 07:16:07 received ENODEV (unmount request), thread exiting
Line: 2024/04/25 07:16:07 received ENODEV (unmount request), thread exiting
Line: 2024/04/25 07:16:07 received ENODEV (unmount request), thread exiting
Line: panic: sync: negative WaitGroup counter
Line: 
Line: goroutine 7278 [running]:
Line: sync.(*WaitGroup).Add(0x12f2780?, 0xc001158a58?)
Line: 	/usr/local/go/src/sync/waitgroup.go:62 +0xd8
Line: sync.(*WaitGroup).Done(0xc000363e40?)
Line: 	/usr/local/go/src/sync/waitgroup.go:87 +0x1a
Line: github.com/hanwen/go-fuse/v2/fuse.(*Server).loop(0xc0011589c0, 0xd0?)
Line: 	/home/marius/go/pkg/mod/github.com/hanwen/go-fuse/v2@v2.5.1/fuse/server.go:503 +0x22a
Line: created by github.com/hanwen/go-fuse/v2/fuse.(*Server).readRequest in goroutine 7225
Line: 	/home/marius/go/pkg/mod/github.com/hanwen/go-fuse/v2@v2.5.1/fuse/server.go:367 +0x549

These are my mount options:

	server, err := fs.Mount(d.pathToMount, root, &fs.Options{
		MountOptions: fuse.MountOptions{Debug: true, AllowOther: true, MaxReadAhead: FileBlockSize, FsName: "drive"},
		Logger: log.New(os.Stderr, "fuse", 0),
	})

I need the lazy unmount as I observed that without lazy, the mount points remain with ????? attribute and can't be removed.

The text was updated successfully, but these errors were encountered:

marius-enlock · 2024-04-25T06:24:43Z

I also found a need on darwin to use /sbin/umount instead of libc_unmount_trampoline, as my filesystem doesn't get unmounted otherwise, would a PR that tries umount in the case the syscall unmount fails be welcomed for darwin?

I am aware that it should be two separate issues, but for the darwin question, I felt it's ok to ask here, as it might be related to why I have the need of lazy unmount on linux.

hanwen · 2024-04-25T10:11:56Z

Line: panic: sync: negative WaitGroup counter

this is a bug in go-fuse. I will have a look tomorrow.

hanwen · 2024-04-25T10:22:58Z

can you confirm that using the race detector to run your file system doesn´t turn up warnings?

marius-enlock · 2024-04-26T02:20:35Z

I was not aware of the race detector. Thank you for pointing out.

I have 4 race warnings in the beginning of my program that are not related to the filesystem. I will fix them and re-try the unmount to see if they affected it somehow.

(Edit: They have to do with context handling - cancelling - inside some unrelated parts of my program)

My program perform a few operations, and after the filesystem gets mounted without any race warnings until I perform the unmount and the above panic happens.

Edit: Running the file system with the race detector doesn't turn up any warnings.

hanwen · 2024-04-26T06:44:00Z

is it possible that you call Server.Serve() twice on the same server?

marius-enlock · 2024-04-26T06:47:43Z

No, I double checked, and I am confident I don't call it twice.

hanwen · 2024-04-26T13:35:57Z

Curious. is there a way I could get my hands on a reproducer? Also, the trace you posted is a smoking gun, but the complete goroutine stacks may be useful too.

hanwen · 2024-04-26T13:46:43Z

wait, this code

/usr/bin/fusermount3" "-uz"

does not exist in go-fuse. Can you reproduce this problem with the latest go-fuse (without local changes?)

marius-enlock · 2024-04-29T03:07:35Z

wait, this code

/usr/bin/fusermount3" "-uz"

does not exist in go-fuse. Can you reproduce this problem with the latest go-fuse (without local changes?)

Yes, the -uz does not exist in go-fuse, the command called from go-fuse without my change is:

"/usr/bin/fusermount3" "-u"

This one works without any issue; go-fuse has no panics as long as the unmount is not attempted in lazy mode.

Curious. is there a way I could get my hands on a reproducer? Also, the trace you posted is a smoking gun, but the complete goroutine stacks may be useful too.

The trace I posted is all I got from my program.

I will try to make a minimum reproducible example.

But for example the following scenario also breaks:

I run the go-fuse filesystem without any change in the library; then on a different terminal I call:

fusermount3 -uz  mounted_folder

The exact same panic happens - this is the full stacktrace my program prints.

Line: panic: sync: negative WaitGroup counter
Line: 
Line: goroutine 7383 [running]:
Line: sync.(*WaitGroup).Add(0x12f2780?, 0xc0048c83d8?)
Line: 	/usr/local/go/src/sync/waitgroup.go:62 +0xd8
Line: sync.(*WaitGroup).Done(0x0?)
Line: 	/usr/local/go/src/sync/waitgroup.go:87 +0x1a
Line: github.com/hanwen/go-fuse/v2/fuse.(*Server).loop(0xc0048c8340, 0x0?)
Line: 	/home/marius/go/pkg/mod/github.com/hanwen/go-fuse/v2@v2.5.1/fuse/server.go:503 +0x22a
Line: created by github.com/hanwen/go-fuse/v2/fuse.(*Server).readRequest in goroutine 7284
Line: 	/home/marius/go/pkg/mod/github.com/hanwen/go-fuse/v2@v2.5.1/fuse/server.go:367 +0x549

marius-enlock · 2024-04-29T03:21:38Z

Edit: I edited the example.

Here is a full reproducible example (I had modified the example for the loopback):
The modification is at the end of the program, in how the file system gets mounted

// Copyright 2016 the Go-FUSE Authors. All rights reserved.
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.

// This is main program driver for the loopback filesystem from
// github.com/hanwen/go-fuse/fs/, a filesystem that shunts operations
// to an underlying file system.
package main

import (
	"flag"
	"fmt"
	"log"
	"os"
	"os/signal"
	"path"
	"runtime/pprof"
	"syscall"
	"time"

	"github.com/hanwen/go-fuse/v2/fs"
	"github.com/hanwen/go-fuse/v2/fuse"
)

func writeMemProfile(fn string, sigs <-chan os.Signal) {
	i := 0
	for range sigs {
		fn := fmt.Sprintf("%s-%d.memprof", fn, i)
		i++

		log.Printf("Writing mem profile to %s\n", fn)
		f, err := os.Create(fn)
		if err != nil {
			log.Printf("Create: %v", err)
			continue
		}
		pprof.WriteHeapProfile(f)
		if err := f.Close(); err != nil {
			log.Printf("close %v", err)
		}
	}
}

func main() {
	log.SetFlags(log.Lmicroseconds)
	// Scans the arg list and sets up flags
	debug := flag.Bool("debug", false, "print debugging messages.")
	other := flag.Bool("allow-other", false, "mount with -o allowother.")
	quiet := flag.Bool("q", false, "quiet")
	ro := flag.Bool("ro", false, "mount read-only")
	directmount := flag.Bool("directmount", false, "try to call the mount syscall instead of executing fusermount")
	directmountstrict := flag.Bool("directmountstrict", false, "like directmount, but don't fall back to fusermount")
	cpuprofile := flag.String("cpuprofile", "", "write cpu profile to this file")
	memprofile := flag.String("memprofile", "", "write memory profile to this file")
	flag.Parse()
	if flag.NArg() < 2 {
		fmt.Printf("usage: %s MOUNTPOINT ORIGINAL\n", path.Base(os.Args[0]))
		fmt.Printf("\noptions:\n")
		flag.PrintDefaults()
		os.Exit(2)
	}
	if *cpuprofile != "" {
		if !*quiet {
			fmt.Printf("Writing cpu profile to %s\n", *cpuprofile)
		}
		f, err := os.Create(*cpuprofile)
		if err != nil {
			fmt.Println(err)
			os.Exit(3)
		}
		pprof.StartCPUProfile(f)
		defer pprof.StopCPUProfile()
	}
	if *memprofile != "" {
		if !*quiet {
			log.Printf("send SIGUSR1 to %d to dump memory profile", os.Getpid())
		}
		profSig := make(chan os.Signal, 1)
		signal.Notify(profSig, syscall.SIGUSR1)
		go writeMemProfile(*memprofile, profSig)
	}
	if *cpuprofile != "" || *memprofile != "" {
		if !*quiet {
			fmt.Printf("Note: You must unmount gracefully, otherwise the profile file(s) will stay empty!\n")
		}
	}

	orig := flag.Arg(1)
	loopbackRoot, err := fs.NewLoopbackRoot(orig)
	if err != nil {
		log.Fatalf("NewLoopbackRoot(%s): %v\n", orig, err)
	}

	sec := time.Second
	opts := &fs.Options{
		// The timeout options are to be compatible with libfuse defaults,
		// making benchmarking easier.
		AttrTimeout:  &sec,
		EntryTimeout: &sec,

		NullPermissions: true, // Leave file permissions on "000" files as-is

		MountOptions: fuse.MountOptions{
			AllowOther:        *other,
			Debug:             *debug,
			DirectMount:       *directmount,
			DirectMountStrict: *directmountstrict,
			FsName:            orig,       // First column in "df -T": original dir
			Name:              "loopback", // Second column in "df -T" will be shown as "fuse." + Name
		},
	}
	if opts.AllowOther {
		// Make the kernel check file permissions for us
		opts.MountOptions.Options = append(opts.MountOptions.Options, "default_permissions")
	}
	if *ro {
		opts.MountOptions.Options = append(opts.MountOptions.Options, "ro")
	}
	// Enable diagnostics logging
	if !*quiet {
		opts.Logger = log.New(os.Stderr, "", 0)
	}
	server, err := fs.Mount(flag.Arg(0), loopbackRoot, opts)
	if err != nil {
		log.Fatalf("Mount fail: %v\n", err)
	}
	if !*quiet {
		fmt.Println("Mounted!")
	}

	c := make(chan os.Signal)
	d := make(chan bool)
	signal.Notify(c, os.Interrupt, syscall.SIGTERM)
	go func() {
		<-c
		close(d)
		server.Unmount()
	}()

	e := make(chan bool)

	go func() { e <- true }()
	for {
		select {
		case <-d:
			time.Sleep(10 * time.Second)
			break
		case <-e:
			server.Serve()
		}
	}
}

calling fusermount3 -uz mounted_folder (t1 in the example) results in:

marius@marsik:~/work/enlock/code/go-fuse/example/loopback$ go run main.go t1 t2
Mounted!
panic: sync: negative WaitGroup counter

goroutine 1 [running]:
sync.(*WaitGroup).Add(0x51f560?, 0xc00008a8b8?)
        /usr/local/go/src/sync/waitgroup.go:62 +0xd8
sync.(*WaitGroup).Done(0x0?)
        /usr/local/go/src/sync/waitgroup.go:87 +0x1a
github.com/hanwen/go-fuse/v2/fuse.(*Server).loop(0xc00008a820, 0x2?)
        /home/marius/go/pkg/mod/github.com/hanwen/go-fuse/v2@v2.5.1/fuse/server.go:503 +0x22a
github.com/hanwen/go-fuse/v2/fuse.(*Server).Serve(0xc00008a820)
        /home/marius/go/pkg/mod/github.com/hanwen/go-fuse/v2@v2.5.1/fuse/server.go:422 +0x35
main.main()
        /home/marius/work/enlock/code/go-fuse/example/loopback/main.go:149 +0xb6c
exit status 2

marius-enlock · 2024-04-29T04:14:57Z

In the provided example, the panic happens also without the lazy unmount flag (just ctrl+c from the terminal that launched it)

hanwen · 2024-04-30T19:08:57Z

This is quite odd. Somehow the infinite loop is causing this to happen. Trimmed down code:

package main

import (
	"flag"
	"fmt"
	"log"
	"os"
	"path"

	"github.com/hanwen/go-fuse/v2/fs"
	"github.com/hanwen/go-fuse/v2/fuse"
)

func main() {
	log.SetFlags(log.Lmicroseconds)
	// Scans the arg list and sets up flags
	debug := flag.Bool("debug", false, "print debugging messages.")
	quiet := flag.Bool("q", false, "quiet")
	flag.Parse()
	if flag.NArg() < 2 {
		fmt.Printf("usage: %s MOUNTPOINT ORIGINAL\n", path.Base(os.Args[0]))
		fmt.Printf("\noptions:\n")
		flag.PrintDefaults()
		os.Exit(2)
	}

	orig := flag.Arg(1)
	loopbackRoot, err := fs.NewLoopbackRoot(orig)
	if err != nil {
		log.Fatalf("NewLoopbackRoot(%s): %v\n", orig, err)
	}

	opts := &fs.Options{
		MountOptions: fuse.MountOptions{
			Debug: *debug,
		},
	}
	// Enable diagnostics logging
	opts.Logger = log.New(os.Stderr, "", 0)
	server, err := fs.Mount(flag.Arg(0), loopbackRoot, opts)
	if err != nil {
		log.Fatalf("Mount fail: %v\n", err)
	}
	if !*quiet {
		fmt.Println("Mounted!")
	}

	e := make(chan bool)
	go func() { e <- true }()
	for {
		select {
		case <-e:
			log.Println("serve")
			server.Serve()
			log.Println("serve done!")
			server = nil
		}
	}
}

rfjakob · 2024-04-30T20:39:01Z

It's not the loop. Adding a sleep at the bottom also shows the panic. My guess now is that it always panics on unmount, but most of the time the process exists before the panic is printed.

package main

import (
	"flag"
	"fmt"
	"log"
	"os"
	"path"
	"time"

	"github.com/hanwen/go-fuse/v2/fs"
	"github.com/hanwen/go-fuse/v2/fuse"
)

func main() {
	log.SetFlags(log.Lmicroseconds)
	flag.Parse()
	if flag.NArg() < 2 {
		fmt.Printf("usage: %s MOUNTPOINT ORIGINAL\n", path.Base(os.Args[0]))
		fmt.Printf("\noptions:\n")
		flag.PrintDefaults()
		os.Exit(2)
	}

	orig := flag.Arg(1)
	loopbackRoot, err := fs.NewLoopbackRoot(orig)
	if err != nil {
		log.Fatalf("NewLoopbackRoot(%s): %v\n", orig, err)
	}

	opts := &fs.Options{
		MountOptions: fuse.MountOptions{
			Debug: true,
		},
	}
	// Enable diagnostics logging
	opts.Logger = log.New(os.Stderr, "", 0)
	server, err := fs.Mount(flag.Arg(0), loopbackRoot, opts)
	if err != nil {
		log.Fatalf("Mount fail: %v\n", err)
	}

	fmt.Println("serve")
	server.Serve()
	fmt.Println("serve done!")
	server = nil

	time.Sleep(1 * time.Second)
}

rfjakob · 2024-04-30T20:49:39Z

This is calling Serve() twice. Once implicitely via fs.Mount(), once explicitely via server.Serve().

rfjakob · 2024-04-30T21:14:42Z

I suggest https://review.gerrithub.io/c/hanwen/go-fuse/+/1194109/2

Calling Serve() multiple times leads to a panic on unmount and fun debugging sessions ( #512 ). Catch it early. Change-Id: I3c490448fa3b8407a6db1bd8ad94b8a4e1a93828

marius-enlock changed the title ~~Panic when unmounting with lazy option on fusermount3 linux~~ Issues when unmounting on linux/ darwin Apr 25, 2024

hanwen pushed a commit that referenced this issue May 15, 2024

fuse: Server: catch duplicate Serve() calls

4ee2ee4

Calling Serve() multiple times leads to a panic on unmount and fun debugging sessions ( #512 ). Catch it early. Change-Id: I3c490448fa3b8407a6db1bd8ad94b8a4e1a93828

hanwen closed this as completed May 17, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Issues when unmounting on linux/ darwin #512

Issues when unmounting on linux/ darwin #512

marius-enlock commented Apr 25, 2024 •

edited

marius-enlock commented Apr 25, 2024 •

edited

hanwen commented Apr 25, 2024

hanwen commented Apr 25, 2024

marius-enlock commented Apr 26, 2024 •

edited

hanwen commented Apr 26, 2024

marius-enlock commented Apr 26, 2024

hanwen commented Apr 26, 2024

hanwen commented Apr 26, 2024

marius-enlock commented Apr 29, 2024 •

edited

marius-enlock commented Apr 29, 2024 •

edited

marius-enlock commented Apr 29, 2024

hanwen commented Apr 30, 2024

rfjakob commented Apr 30, 2024

rfjakob commented Apr 30, 2024

rfjakob commented Apr 30, 2024

Issues when unmounting on linux/ darwin #512

Issues when unmounting on linux/ darwin #512

Comments

marius-enlock commented Apr 25, 2024 • edited

marius-enlock commented Apr 25, 2024 • edited

hanwen commented Apr 25, 2024

hanwen commented Apr 25, 2024

marius-enlock commented Apr 26, 2024 • edited

hanwen commented Apr 26, 2024

marius-enlock commented Apr 26, 2024

hanwen commented Apr 26, 2024

hanwen commented Apr 26, 2024

marius-enlock commented Apr 29, 2024 • edited

marius-enlock commented Apr 29, 2024 • edited

marius-enlock commented Apr 29, 2024

hanwen commented Apr 30, 2024

rfjakob commented Apr 30, 2024

rfjakob commented Apr 30, 2024

rfjakob commented Apr 30, 2024

marius-enlock commented Apr 25, 2024 •

edited

marius-enlock commented Apr 25, 2024 •

edited

marius-enlock commented Apr 26, 2024 •

edited

marius-enlock commented Apr 29, 2024 •

edited

marius-enlock commented Apr 29, 2024 •

edited