search

mpartel / bindfs

Mount a directory elsewhere with changed permissions.
https://bindfs.org/
GNU General Public License v2.0
436 stars 64 forks source link

bindfs dies silently when network goes down #72

Closed wilderjds closed 5 years ago

wilderjds commented 5 years ago

I am running bindfs between two local dirs; when I disconnect the network (via NetworkManager) as follows:

nmcli radio wifi off

bindfs dies silently. I attach here a stacktrace 

brk(NULL)                               = 0x562dc9d78000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=308785, ...}) = 0
mmap(NULL, 308785, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f0af400f000
close(3)                                = 0
openat(AT_FDCWD, "/usr/lib64/libfuse.so.2", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\360\210\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=249776, ...}) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f0af400d000
mmap(NULL, 2345184, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f0af3bf8000
mprotect(0x7f0af3c23000, 2093056, PROT_NONE) = 0
mmap(0x7f0af3e22000, 77824, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2a000) = 0x7f0af3e22000
close(3)                                = 0
openat(AT_FDCWD, "/lib64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\340b\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=145840, ...}) = 0
mmap(NULL, 2225248, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f0af39d8000
mprotect(0x7f0af39f3000, 2093056, PROT_NONE) = 0
mmap(0x7f0af3bf2000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1a000) = 0x7f0af3bf2000
mmap(0x7f0af3bf4000, 13408, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f0af3bf4000
close(3)                                = 0
openat(AT_FDCWD, "/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0\34\2\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1857312, ...}) = 0
mmap(NULL, 3963464, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f0af3610000
mprotect(0x7f0af37ce000, 2097152, PROT_NONE) = 0
mmap(0x7f0af39ce000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1be000) = 0x7f0af39ce000
mmap(0x7f0af39d4000, 14920, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f0af39d4000
close(3)                                = 0
openat(AT_FDCWD, "/lib64/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0 \16\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=14320, ...}) = 0
mmap(NULL, 2109712, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f0af340c000
mprotect(0x7f0af340f000, 2093056, PROT_NONE) = 0
mmap(0x7f0af360e000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7f0af360e000
close(3)                                = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f0af400b000
arch_prctl(ARCH_SET_FS, 0x7f0af400bb80) = 0
mprotect(0x7f0af39ce000, 16384, PROT_READ) = 0
mprotect(0x7f0af360e000, 4096, PROT_READ) = 0
mprotect(0x7f0af3bf2000, 4096, PROT_READ) = 0
mprotect(0x7f0af3e22000, 73728, PROT_READ) = 0
mprotect(0x562dc9b24000, 4096, PROT_READ) = 0
mprotect(0x7f0af405b000, 4096, PROT_READ) = 0
munmap(0x7f0af400f000, 308785)          = 0
set_tid_address(0x7f0af400be50)         = 18574
set_robust_list(0x7f0af400be60, 24)     = 0
rt_sigaction(SIGRTMIN, {sa_handler=0x7f0af39ddca0, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x7f0af39ec0a0}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {sa_handler=0x7f0af39ddd50, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_SIGINFO, sa_restorer=0x7f0af39ec0a0}, NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
prlimit64(0, RLIMIT_STACK, NULL, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
brk(NULL)                               = 0x562dc9d78000
brk(0x562dc9d99000)                     = 0x562dc9d99000
getcwd("/home/jacopods", 4096)          = 15
getuid()                                = 0
lstat("/home", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/home/jacopods", {st_mode=S_IFDIR|0755, st_size=20480, ...}) = 0
lstat("/home", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/home/jacopods", {st_mode=S_IFDIR|0755, st_size=20480, ...}) = 0
lstat("/home/jacopods/.dropbox.utoronto", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
openat(AT_FDCWD, "/home/jacopods", O_RDONLY) = 3
umask(000)                              = 022
rt_sigaction(SIGUSR1, {sa_handler=0x562dc991d890, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f0af39ec0a0}, NULL, 8) = 0
lstat("/home", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/home/jacopods", {st_mode=S_IFDIR|0755, st_size=20480, ...}) = 0
lstat("/home/jacopods/.dropbox.utoronto", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
openat(AT_FDCWD, "/dev/null", O_RDWR)   = 4
close(4)                                = 0
stat("/home/jacopods/.dropbox.utoronto", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
openat(AT_FDCWD, "/home/jacopods/.dropbox.utoronto", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 4
fstat(4, {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
getdents(4, /* 2 entries */, 32768)     = 48
getdents(4, /* 0 entries */, 32768)     = 0
close(4)                                = 0
openat(AT_FDCWD, "/dev/fuse", O_RDWR)   = 4
getgid()                                = 0
getuid()                                = 0
mount("/home/jacopods", "/home/jacopods/.dropbox.utoronto", "fuse", MS_NOSUID|MS_NODEV, "allow_other,default_permissions,"...) = 0
geteuid()                               = 0
lstat("/home", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/home/jacopods", {st_mode=S_IFDIR|0755, st_size=20480, ...}) = 0
lstat("/etc/mtab", {st_mode=S_IFLNK|0777, st_size=17, ...}) = 0
write(2, "FUSE library version: 2.9.8\n", 28FUSE library version: 2.9.8
) = 28
getuid()                                = 0
write(2, "nullpath_ok: 0\n", 15nullpath_ok: 0
)        = 15
write(2, "nopath: 0\n", 10nopath: 0
)             = 10
write(2, "utime_omit_ok: 0\n", 17utime_omit_ok: 0
)      = 17
brk(0x562dc9dbd000)                     = 0x562dc9dbd000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f0af405a000
rt_sigaction(SIGHUP, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGHUP, {sa_handler=0x7f0af3c11fe0, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f0af39ec0a0}, NULL, 8) = 0
rt_sigaction(SIGINT, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGINT, {sa_handler=0x7f0af3c11fe0, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f0af39ec0a0}, NULL, 8) = 0
rt_sigaction(SIGTERM, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGTERM, {sa_handler=0x7f0af3c11fe0, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f0af39ec0a0}, NULL, 8) = 0
rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f0af39ec0a0}, NULL, 8) = 0
mmap(NULL, 139264, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f0af4038000
read(4, "8\0\0\0\32\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 135168) = 56
write(2, "unique: 2, opcode: INIT (26), no"..., 60unique: 2, opcode: INIT (26), nodeid: 0, insize: 56, pid: 0
) = 60
write(2, "INIT: 7.28\n", 11INIT: 7.28
)            = 11
write(2, "flags=0x00fffffb\n", 17flags=0x00fffffb
)      = 17
write(2, "max_readahead=0x00020000\n", 25max_readahead=0x00020000
) = 25
fchdir(3)                               = 0
write(2, "   INIT: 7.19\n", 14   INIT: 7.19
)         = 14
write(2, "   flags=0x00000011\n", 20   flags=0x00000011
)   = 20
write(2, "   max_readahead=0x00020000\n", 28   max_readahead=0x00020000
) = 28
write(2, "   max_write=0x00020000\n", 24   max_write=0x00020000
) = 24
write(2, "   max_background=0\n", 20   max_background=0
)   = 20
write(2, "   congestion_threshold=0\n", 26   congestion_threshold=0
) = 26
write(2, "   unique: 2, success, outsize: "..., 35   unique: 2, success, outsize: 40
) = 35
writev(4, [{iov_base="(\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0", iov_len=16}, {iov_base="\7\0\0\0\23\0\0\0\0\0\2\0\21\0\0\0\0\0\0\0\0\0\2\0", iov_len=24}], 2) = 40
read(4, "8\0\0\0\3\0\0\0\4\0\0\0\0\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 135168) = 56

----- Network is disconnected now ----

write(2, "unique: 4, opcode: GETATTR (3), "..., 66unique: 4, opcode: GETATTR (3), nodeid: 1, insize: 56, pid: 18649
) = 66
write(2, "getattr /\n", 10getattr /
)             = 10
lstat(".", {st_mode=S_IFDIR|0755, st_size=20480, ...}) = 0
write(2, "   unique: 4, success, outsize: "..., 36   unique: 4, success, outsize: 120
) = 36
writev(4, [{iov_base="x\0\0\0\0\0\0\0\4\0\0\0\0\0\0\0", iov_len=16}, {iov_base="\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\1\0\36\0\0\0\0\0\0P\0\0\0\0\0\0"..., iov_len=104}], 2) = 120
read(4, 0x7f0af4038010, 135168)         = -1 ENODEV (No such device)
munmap(0x7f0af4038000, 139264)          = 0
rt_sigaction(SIGHUP, NULL, {sa_handler=0x7f0af3c11fe0, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f0af39ec0a0}, 8) = 0
rt_sigaction(SIGHUP, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f0af39ec0a0}, NULL, 8) = 0
rt_sigaction(SIGINT, NULL, {sa_handler=0x7f0af3c11fe0, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f0af39ec0a0}, 8) = 0
rt_sigaction(SIGINT, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f0af39ec0a0}, NULL, 8) = 0
rt_sigaction(SIGTERM, NULL, {sa_handler=0x7f0af3c11fe0, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f0af39ec0a0}, 8) = 0
rt_sigaction(SIGTERM, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f0af39ec0a0}, NULL, 8) = 0
rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f0af39ec0a0}, 8) = 0
rt_sigaction(SIGPIPE, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f0af39ec0a0}, NULL, 8) = 0
poll([{fd=4, events=0}], 1, 0)          = 1 ([{fd=4, revents=POLLERR}])
close(4)                                = 0
munmap(0x7f0af405a000, 4096)            = 0
close(3)                                = 0
exit_group(0)                           = ?
+++ exited with 0 +++
mpartel commented 5 years ago

Sadly I can't reproduce this.

The essential lines seem to be:

openat(AT_FDCWD, "/dev/fuse", O_RDWR)   = 4
...
read(4, 0x7f0af4038010, 135168)         = -1 ENODEV (No such device)

http://man7.org/linux/man-pages/man4/fuse.4.html says ENODEV is returned "if the FUSE filesystem was unmounted".

My first guess is that NetworkManager thinks bindfs is a networked FS and tries to unmount it. Is bindfs perhaps mounted on top of a networked FS of some sort? (your strace mentions dropbox) Is there anything interesting in the kernel's or NetworkManager's logs?

wilderjds commented 5 years ago

Here follows the NetworkManager log; I will also have a look at it

Feb 27 06:58:10 bl4ckspoons avahi-daemon[3344]: Registering new address record for 2607:fea8:7df:f8fc:e6b3:18ff:fe75:1a75 on wlp4s0.*.
Feb 27 06:58:10 bl4ckspoons NetworkManager[3261]: <debug> [1551268690.0437] platform: signal: address 6   added: 2607:fea8:7df:f8fc:e6b3:18ff:fe75:1a75/64 lft 604799sec pref 172799sec lifetime 30800-30798[172801,604801] dev 3 flags mngtmpaddr src kernel
Feb 27 06:58:10 bl4ckspoons NetworkManager[3261]: <debug> [1551268690.0437] device[0x5645adb128a0] (wlp4s0): queued IP6 config change
Feb 27 06:58:10 bl4ckspoons NetworkManager[3261]: <debug> [1551268690.0438] device[0x5645adb128a0] (wlp4s0): ip6-config: update (commit=0, new-config=0x5645adb0cc30)
Feb 27 06:58:10 bl4ckspoons NetworkManager[3261]: <debug> [1551268690.0440] device[0x5645adb128a0] (wlp4s0): ip6-config: update IP Config instance (/org/freedesktop/NetworkManager/IP6Config/10)
Feb 27 06:58:10 bl4ckspoons NetworkManager[3261]: <debug> [1551268690.0440] dns-mgr: (device_ip_config_changed): queueing DNS updates (1)
Feb 27 06:58:10 bl4ckspoons NetworkManager[3261]: <debug> [1551268690.0440] dns-mgr: (device_ip_config_changed): DNS configuration did not change
Feb 27 06:58:10 bl4ckspoons NetworkManager[3261]: <debug> [1551268690.0440] dns-mgr: (device_ip_config_changed): no DNS changes to commit (0)
Feb 27 06:58:27 bl4ckspoons NetworkManager[3261]: <debug> [1551268707.1147] device[0x5645adb128a0] (wlp4s0): wifi-scan: scanning requested but not allowed at this time
Feb 27 06:58:27 bl4ckspoons NetworkManager[3261]: <debug> [1551268707.1148] device[0x5645adb128a0] (wlp4s0): wifi-scan: scheduled in 43 seconds (interval now 43 seconds)
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.6691] manager: rfkill: (WiFi): setting radio disabled by user
Feb 27 06:59:00 bl4ckspoons avahi-daemon[3344]: Interface wlp4s0.IPv6 no longer relevant for mDNS.
Feb 27 06:59:00 bl4ckspoons avahi-daemon[3344]: Leaving mDNS multicast group on interface wlp4s0.IPv6 with address fd00:f81d:f81:24f2:e6b3:18ff:fe75:1a75.
Feb 27 06:59:00 bl4ckspoons dhclient: receive_packet failed on wlp4s0: Network is down
Feb 27 06:59:00 bl4ckspoons avahi-daemon[3344]: Interface wlp4s0.IPv4 no longer relevant for mDNS.
Feb 27 06:59:00 bl4ckspoons avahi-daemon[3344]: Leaving mDNS multicast group on interface wlp4s0.IPv4 with address 192.168.0.37.
Feb 27 06:59:00 bl4ckspoons avahi-daemon[3344]: Withdrawing address record for 2607:fea8:7df:f8fc:e6b3:18ff:fe75:1a75 on wlp4s0.
Feb 27 06:59:00 bl4ckspoons avahi-daemon[3344]: Withdrawing address record for fd00:f81d:f81:24f2:e6b3:18ff:fe75:1a75 on wlp4s0.
Feb 27 06:59:00 bl4ckspoons avahi-daemon[3344]: Withdrawing address record for 192.168.0.37 on wlp4s0.
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <info>  [1551268740.7018] manager: rfkill: WiFi hardware radio set disabled
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7018] manager: (wlp4s0): rfkill: setting radio disabled
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7018] device[0x5645adb128a0] (wlp4s0): device now disabled
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <info>  [1551268740.7018] device (wlp4s0): state change: activated -> unavailable (reason 'none', sys-iface-state: 'managed')
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7019] device[0x5645adb128a0] (wlp4s0): deactivating device (reason 'none') [0]
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7019] firewall: [0x5645adae6e30,remove*:"wlp4s0"]: firewall zone remove wlp4s0:default (not running, simulate success)
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7028] firewall: [0x5645adae6e30,remove*:"wlp4s0"]: complete: drop request simulating success
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7029] kill child process 'dhcp-client-wlp4s0' (17331): waiting up to 500 milliseconds for process to terminate normally after sending SIGTERM (15)...
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7107] kill child process 'dhcp-client-wlp4s0' (17331): after sending SIGTERM (15), process 17331 exited by signal 15 (7823 usec elapsed)
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <info>  [1551268740.7108] dhcp4 (wlp4s0): canceled DHCP transaction, DHCP client pid 17331
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <info>  [1551268740.7108] dhcp4 (wlp4s0): state changed bound -> done
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7111] platform-linux: sysctl: setting '/proc/sys/net/ipv6/conf/wlp4s0/disable_ipv6' to '1' (current value is '0')
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7112] platform-linux: sysctl: setting '/proc/sys/net/ipv6/conf/wlp4s0/accept_ra' to '0' (current value is '1')
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7112] platform-linux: sysctl: setting '/proc/sys/net/ipv6/conf/wlp4s0/use_tempaddr' to '0' (current value is identical)
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7114] platform: ip4-route: delete 192.168.0.0/24 via 0.0.0.0 dev 3 metric 600 mss 0 rt-src rt-kernel scope link pref-src 192.168.0.37
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7115] platform: signal: link changed: 3: wlp4s0 <DOWN;broadcast,multicast> mtu 1500 arp 1 wifi? init addrgenmode eui64 addr E4:B3:18:75:1A:75 driver iwlwifi rx:159632,193106293 tx:47315,14025337
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7115] device[0x5645adb128a0] (wlp4s0): queued link change for ifindex 3
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7115] platform: signal: route   6 removed: 2607:fea8:7df:f8fc::/64 via :: dev 3 metric 256 mss 0 rt-src rt-kernel
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7115] device[0x5645adb128a0] (wlp4s0): queued IP6 config change
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7116] platform: signal: route   6 removed: fd00:f81d:f81:24f2::/64 via :: dev 3 metric 256 mss 0 rt-src rt-kernel
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7116] platform: signal: route   6 removed: fe80::/64 via :: dev 3 metric 256 mss 0 rt-src rt-kernel
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7116] platform: signal: route   6 removed: ff00::/8 via :: dev 3 metric 256 mss 0 rt-src rt-boot
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7116] platform: signal: route   6 removed: ::/0 via fe80::fa1d:fff:fe81:24f2 dev 3 metric 1024 mss 0 rt-src rt-ra
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7116] platform: signal: address 6 removed: fd00:f81d:f81:24f2:e6b3:18ff:fe75:1a75/64 lft 535377sec pref 401520sec lifetime 30850-30798[401572,535429] dev 3 flags mngtmpaddr src kernel
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7117] platform: signal: address 6 removed: 2607:fea8:7df:f8fc:e6b3:18ff:fe75:1a75/64 lft 604749sec pref 172749sec lifetime 30850-30798[172801,604801] dev 3 flags mngtmpaddr src kernel
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7117] platform: signal: address 6 removed: fe80::e6b3:18ff:fe75:1a75/64 lft forever pref forever lifetime 30850-0[4294967295,4294967295] dev 3 flags permanent src kernel
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7117] platform-linux: netlink: recvmsg: error message from kernel: No such process (3) for request 241
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7118] platform: signal: route   4 removed: 192.168.0.0/24 via 0.0.0.0 dev 3 metric 600 mss 0 rt-src rt-kernel scope link pref-src 192.168.0.37
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7118] device[0x5645adb128a0] (wlp4s0): queued IP4 config change
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7118] platform: signal: route   4 removed: 0.0.0.0/0 via 192.168.0.1 dev 3 metric 600 mss 0 rt-src rt-dhcp scope global
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7118] platform-linux: do-delete-ip4-route[192.168.0.0/24 via 0.0.0.0 dev 3 metric 600 mss 0 rt-src rt-kernel scope link pref-src 192.168.0.37]: failure 3 (No such process), meaning the object was already removed
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7118] platform: address: deleting IPv4 address 192.168.0.37/24, ifindex 3 dev wlp4s0
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7119] platform: signal: address 4 removed: 192.168.0.37/24 lft 604747sec pref 604747sec lifetime 30850-30796[604801,604801] dev 3 flags noprefixroute src kernel
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7119] platform-linux: do-delete-ip4-address[3: 192.168.0.37/24]: success
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7119] device[0x5645adb128a0] (wlp4s0): set metered value 0
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7120] manager: new metered value: 0
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7121] device[0x5645adb128a0] (wlp4s0): taking down device 3
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7121] platform: link: setting down "wlp4s0" (3)
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7121] platform-linux: link: change 3: flags: set 0x0/0x1 ([] / [up])
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7121] platform-linux: do-request-link: 3 
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7121] platform-linux: do-change-link[3]: success changing link: success
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7121] platform: link: setting "wlp4s0" (3) hardware address to 76:F6:85:C7:86:75
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7122] platform-linux: do-request-link: 3 
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7122] platform: signal: link changed: 3: wlp4s0 <DOWN;broadcast,multicast> mtu 1500 arp 1 wifi? init addrgenmode eui64 addr 76:F6:85:C7:86:75 driver iwlwifi rx:159632,193106293 tx:47315,14025337
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7122] platform-linux: do-change-link[3]: success changing link: success
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7122] device[0x5645adb128a0] (wlp4s0): hw-addr: hardware address now 76:F6:85:C7:86:75
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <info>  [1551268740.7123] device (wlp4s0): set-hw-addr: set MAC address to 76:F6:85:C7:86:75 (scanning)
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7124] device[0x5645adb128a0] (wlp4s0): bringing up device ignored due to disabled
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7124] device[0x5645adb128a0] (wlp4s0): ip4-config: update (commit=1, new-config=(nil))
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7124] device[0x5645adb128a0] (wlp4s0): ip4-config: clear IP Config instance (/org/freedesktop/NetworkManager/IP4Config/10)
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7125] dns-mgr: (device_ip_config_changed): queueing DNS updates (1)
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7126] dns-mgr: (device_ip_config_changed): DNS configuration changed
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7126] dns-mgr: (device_ip_config_changed): committing DNS changes (0)
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7126] dns-mgr: update-dns: not updating resolv.conf
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7127] device[0x5645adb128a0] (wlp4s0): ip6-config: update (commit=1, new-config=(nil))
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7128] device[0x5645adb128a0] (wlp4s0): ip6-config: clear IP Config instance (/org/freedesktop/NetworkManager/IP6Config/10)
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7129] dns-mgr: (device_ip_config_changed): queueing DNS updates (1)
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7129] dns-mgr: (device_ip_config_changed): DNS configuration did not change
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7129] dns-mgr: (device_ip_config_changed): no DNS changes to commit (0)
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7136] active-connection[0x5645ada16ca0]: set state deactivated (was activated)
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <info>  [1551268740.7138] manager: NetworkManager state is now DISCONNECTED
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7138] active-connection[0x5645ada16ca0]: check-master-ready: not signalling (state deactivated, no master)
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7197] device[0x5645adb128a0] (wlp4s0): wifi-scan: reset interval to 23 seconds
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7478] dns-mgr: (update_routing_and_dns): queueing DNS updates (1)
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7479] manager: PrimaryConnection now (none)
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7479] dns-mgr: (update_routing_and_dns): DNS configuration did not change
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7479] dns-mgr: (update_routing_and_dns): no DNS changes to commit (0)
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7479] device[0x5645adb128a0] (wlp4s0): device not yet available for transition to DISCONNECTED
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7479] dispatcher: (31) (wlp4s0) dispatching action 'down'
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7486] device[0x5645adb128a0] (wlp4s0): connectivity state changed from FULL to NONE
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7486] manager: connectivity checking indicates NONE
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7486] dispatcher: (32) dispatching action 'connectivity-change'
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7487] device[0x5645adb128a0] (wlp4s0): taking down device 3
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7487] platform: link: setting down "wlp4s0" (3)
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7487] platform-linux: link: change 3: flags: set 0x0/0x1 ([] / [up])
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7487] platform-linux: do-request-link: 3 
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7488] platform-linux: do-change-link[3]: success changing link: success
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <info>  [1551268740.7489] audit: op="radio-control" arg="wireless-enabled" pid=17747 uid=1000 result="success"
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7490] udev rfkill event: action 'change' device 'rfkill2'
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7491] WiFi rfkill switch rfkill2 state now 0/1
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7491] WiFi rfkill state now 'soft-blocked'
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7491] manager: rfkill: WiFi hw-enabled 1 sw-enabled 0
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <info>  [1551268740.7492] manager: rfkill: WiFi now disabled by radio killswitch
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7501] device[0x5645adb128a0] (wlp4s0): ip6-config: update (commit=0, new-config=0x5645adb0c7f0)
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7503] device[0x5645adb128a0] (wlp4s0): ip6-config: set IP Config instance (/org/freedesktop/NetworkManager/IP6Config/11)
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7504] dns-mgr: (device_ip_config_changed): queueing DNS updates (1)
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7504] dns-mgr: (device_ip_config_changed): DNS configuration did not change
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7504] dns-mgr: (device_ip_config_changed): no DNS changes to commit (0)
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7505] device[0x5645adb128a0] (wlp4s0): ip4-config: update (commit=0, new-config=0x5645ada16ad0)
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7506] device[0x5645adb128a0] (wlp4s0): ip4-config: set IP Config instance (/org/freedesktop/NetworkManager/IP4Config/11)
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7507] dns-mgr: (device_ip_config_changed): queueing DNS updates (1)
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7507] dns-mgr: (device_ip_config_changed): DNS configuration did not change
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7507] dns-mgr: (device_ip_config_changed): no DNS changes to commit (0)
Feb 27 06:59:00 bl4ckspoons NetworkManager[3261]: <debug> [1551268740.7508] active-connection[0x5645ada16ca0]: disposing
Feb 27 06:59:00 bl4ckspoons dbus[3147]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Feb 27 06:59:00 bl4ckspoons dbus[3147]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Feb 27 06:59:00 bl4ckspoons nm-dispatcher: req:1 'down' [wlp4s0]: new request (1 scripts)
Feb 27 06:59:00 bl4ckspoons nm-dispatcher: req:1 'down' [wlp4s0]: environment: CONNECTION_DBUS_PATH=/org/freedesktop/NetworkManager/Settings/6
Feb 27 06:59:00 bl4ckspoons nm-dispatcher: req:1 'down' [wlp4s0]: environment: CONNECTION_FILENAME=/etc/NetworkManager/system-connections/tamara-5g.nmconnection
Feb 27 06:59:00 bl4ckspoons nm-dispatcher: req:1 'down' [wlp4s0]: environment: CONNECTION_UUID=4b55c602-6ba9-47f5-a59b-888b6fcd7949
Feb 27 06:59:00 bl4ckspoons nm-dispatcher: req:1 'down' [wlp4s0]: environment: CONNECTION_ID=tamara-5g
Feb 27 06:59:00 bl4ckspoons nm-dispatcher: req:1 'down' [wlp4s0]: environment: DEVICE_IFACE=wlp4s0
Feb 27 06:59:00 bl4ckspoons nm-dispatcher: req:1 'down' [wlp4s0]: environment: DEVICE_IP_IFACE=wlp4s0
Feb 27 06:59:00 bl4ckspoons nm-dispatcher: req:1 'down' [wlp4s0]: environment: NM_DISPATCHER_ACTION=down
Feb 27 06:59:00 bl4ckspoons nm-dispatcher: req:1 'down' [wlp4s0]: start running ordered scripts...
Feb 27 06:59:00 bl4ckspoons nm-dispatcher: req:1 'down' [wlp4s0], "/etc/NetworkManager/dispatcher.d/10-openrc-status": run script
Feb 27 06:59:00 bl4ckspoons nm-dispatcher: req:2 'connectivity-change': new request (1 scripts)
Feb 27 06:59:00 bl4ckspoons nm-dispatcher: req:2 'connectivity-change': environment: CONNECTIVITY_STATE=NONE
Feb 27 06:59:00 bl4ckspoons nm-dispatcher: req:2 'connectivity-change': environment: NM_DISPATCHER_ACTION=connectivity-change
Feb 27 06:59:01 bl4ckspoons dnsmasq[17505]: exiting on receipt of SIGTERM
Feb 27 06:59:01 bl4ckspoons nm-dispatcher: req:1 'down' [wlp4s0], "/etc/NetworkManager/dispatcher.d/10-openrc-status": complete
Feb 27 06:59:01 bl4ckspoons nm-dispatcher: req:1 'down' [wlp4s0]: completed (1 scripts)
Feb 27 06:59:01 bl4ckspoons nm-dispatcher: req:2 'connectivity-change': start running ordered scripts...
Feb 27 06:59:01 bl4ckspoons nm-dispatcher: req:2 'connectivity-change', "/etc/NetworkManager/dispatcher.d/10-openrc-status": run script
Feb 27 06:59:01 bl4ckspoons NetworkManager[3261]: <debug> [1551268741.1113] dispatcher: (31) 10-openrc-status succeeded
Feb 27 06:59:01 bl4ckspoons /etc/init.d/NetworkManager[17941]: status: inactive
Feb 27 06:59:01 bl4ckspoons nm-dispatcher: req:2 'connectivity-change', "/etc/NetworkManager/dispatcher.d/10-openrc-status": complete
Feb 27 06:59:01 bl4ckspoons nm-dispatcher: req:2 'connectivity-change': completed (1 scripts)
Feb 27 06:59:01 bl4ckspoons NetworkManager[3261]: <debug> [1551268741.1337] dispatcher: (32) 10-openrc-status succeeded

The issue occurs regardless of the presence of dropbox folders in the mount [in fact I use bindfs for my dropbox folders, but this turns out to be irrelevant; bindfs drops on rfkill even when binding directories that are not attached to dropbox]

[@mpartel edited for formatting]

mpartel commented 5 years ago

The lines about /etc/NetworkManager/dispatcher.d/10-openrc-status gave me an idea. Maybe openrc has a dependency that says "FUSE filesystems require networking" (some of them do), and downing the network triggers openrc to "shut down" its FUSE component, causing an unmount.

It might be worth checking if your distro's man mount or man fuse lists some option to explicitly categorize the mount as non-network-dependent.

And if you're feeling adventurous, I guess you could replace /bin/umount with a wrapper that logs the parent processes somewhere. :)

wilderjds commented 5 years ago

And if you're feeling adventurous, I guess you could replace /bin/umount with a wrapper that logs the parent processes somewhere. :)

Great suggestion; it was openrc indeed. Apparently gentoo considers fuse filesystems to be networked and brings them down when networkmanager is killed via netmount. There is no way to whitelist fuse. I'll report a bug to openrc and see what happens.

Thanks for your time and hints and for not dismissing this issue as “not a bindfs issue”. I'll follow up here with some info about my report to openrc https://bugs.gentoo.org/679106

mpartel commented 5 years ago

Great! I added a note about this to the website's "known issues". I'll close this an CC myself on that gentoo bug so I'll know when to revisit that notice.

I noticed Ubuntu's man mount lists the option _netdev, but there doesn't seem to be an inverse (for bindfs to add automatically).