Open rcorre opened 5 years ago
Weird. Yeah from this log snippet I agree that it appears to be a network connection initialization issue, which definitely points to your VPN. I know nothing about TunnelBear though. Please let us know if disabling the VPN helps.
I can confirm my kbfs filesystem is accessible within seconds of starting on my work VPN, but kbfs consistently takes over 1min to access on my personal machine using TunnelBear VPN.
keybase version:
Client: 2.8.0
Service: 2.8.0
Any ideas what would cause connection issues for a particular VPN? It is only the initial connection that seems to have trouble.
Weird. Sorry I don't know any tips for debugging TunnelBear. On our end, we don't do anything funny as far as I know with accepting connections from VPNs. Everything is just an ordinary TLS connection for us. We do use self-issued certs (hardcoded into the client apps) rather than certs that are accepted by browsers, which is one way we'd be different from normal web traffic.
But I have no good ideas. Sorry!
Any idea what addresses keybase might be trying to reach during this time?
telnet bserver-0.kbfs.keybaseapi.com 443
connects almost immediately, while I'm still waiting for access to my files.
Just had this startup, where it seemed to hang indefinitely on ls .local/share/keybase/fs/private
. These are the logs from when I run that command:
2018-12-23T17:04:06.012141-05:00 ▶ [DEBU FUSE serve.go:787] 1ac <- Getattr [ID=0x2a Node=0x1 Uid=1000 Gid=1000 Pid=5627] 0x0 fl=0
2018-12-23T17:04:06.012192-05:00 ▶ [DEBU FUSE serve.go:853] 1ad -> [ID=0x2a] Getattr valid=1m0s ino=1 size=0 mode=dr-x------
2018-12-23T17:04:09.126516-05:00 ▶ [DEBU FUSE serve.go:787] 1ae <- Getattr [ID=0x2b Node=0x2 Uid=1000 Gid=1000 Pid=5662] 0x0 fl=0
2018-12-23T17:04:09.126565-05:00 ▶ [DEBU FUSE serve.go:853] 1af -> [ID=0x2b] Getattr valid=1m0s ino=2 size=0 mode=dr-x------
2018-12-23T17:04:09.126743-05:00 ▶ [DEBU FUSE serve.go:787] 1b0 <- Getxattr [ID=0x2c Node=0x2 Uid=1000 Gid=1000 Pid=5662] "system.posix_acl_access" 0 @0
2018-12-23T17:04:09.126772-05:00 ▶ [DEBU FUSE serve.go:853] 1b1 -> [ID=0x2c] Getxattr error=operation not supported
2018-12-23T17:04:09.127054-05:00 ▶ [DEBU FUSE serve.go:787] 1b2 <- Open [ID=0x2d Node=0x2 Uid=1000 Gid=1000 Pid=5662] dir=true fl=OpenReadOnly+OpenDirectory+OpenNonblock
2018-12-23T17:04:09.127094-05:00 ▶ [DEBU FUSE serve.go:853] 1b3 -> [ID=0x2d] Open 0x3 fl=0
2018-12-23T17:04:09.127218-05:00 ▶ [DEBU FUSE serve.go:787] 1b4 <- Read [ID=0x2e Node=0x2 Uid=1000 Gid=1000 Pid=5662] 0x3 4096 @0x0 dir=true fl=0 lock=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock
2018-12-23T17:04:09.127247-05:00 ▶ [DEBU kbfs(kbfsfuse) folderlist.go:243] 1b5 FL ReadDirAll [tags:FID=FeRLhzliTsrL3PtlAIhKFA]
2018-12-23T17:04:09.127280-05:00 ▶ [DEBU kbfs(kbfsfuse) folderlist.go:245] 1b6 Request complete [tags:FID=FeRLhzliTsrL3PtlAIhKFA]
2018-12-23T17:04:09.127309-05:00 ▶ [DEBU FUSE serve.go:853] 1b7 -> [ID=0x2e] Read 32
2018-12-23T17:04:09.127463-05:00 ▶ [DEBU FUSE serve.go:787] 1b8 <- Lookup [ID=0x2f Node=0x2 Uid=1000 Gid=1000 Pid=5662] "rcorre"
2018-12-23T17:04:09.127486-05:00 ▶ [DEBU kbfs(kbfsfuse) folderlist.go:166] 1b9 FL Lookup rcorre [tags:FID=fHDRFlPmN2uShWEC0td04g]
2018-12-23T17:04:09.127503-05:00 ▶ [DEBU kbfs(kbfsfuse) folderlist.go:168] 1ba Request complete [tags:FID=fHDRFlPmN2uShWEC0td04g]
After that, nothing happens for minutes. It seems strange that the last thing I see is "request complete". If I disable my vpn, it almost immediately connects and spits out these further log lines:
2018-12-23T17:05:08.505816-05:00 ▶ [DEBU FUSE serve.go:787] 1bb <- Interrupt [ID=0x30 Node=0x0 Uid=0 Gid=0 Pid=0] ID 0x4
2018-12-23T17:05:08.505867-05:00 ▶ [DEBU FUSE serve.go:853] 1bc -> [ID=0x30] Interrupt
2018-12-23T17:05:08.505904-05:00 ▶ [DEBU kbfs(kbfsfuse) tlf.go:87] 1bd context canceled [tags:FID=HaN6VII8R7GmPBa6Qmmv9A]
2018-12-23T17:05:08.505935-05:00 ▶ [DEBU FUSE serve.go:853] 1be -> [ID=0x4] Lookup error=EINTR
2018-12-23T17:05:08.505941-05:00 ▶ [DEBU kbfs(kbfsfuse) tlf.go:157] 1c0 Faking Attr for TLF rcorre [tags:FID=OYvz4nt_LleX5NpEWZRYLQ]
2018-12-23T17:05:08.505998-05:00 ▶ [DEBU FUSE serve.go:853] 1c2 -> [ID=0x29] Lookup 0x3 gen=0 valid=1m0s attr={valid=1s ino=5 size=0 mode=dr-x------}
2018-12-23T17:05:08.505940-05:00 ▶ [DEBU kbfs(kbfsfuse) tlf.go:157] 1bf Faking Attr for TLF rcorre [tags:FID=JzGbvfFi_MWIm9ZWiBU53g]
2018-12-23T17:05:08.506060-05:00 ▶ [DEBU FUSE serve.go:853] 1c3 -> [ID=0x13] Getattr valid=1s ino=5 size=0 mode=dr-x------
2018-12-23T17:05:08.505951-05:00 ▶ [DEBU kbfs(kbfsfuse) tlf.go:157] 1c1 Faking Attr for TLF rcorre [tags:FID=fHDRFlPmN2uShWEC0td04g]
2018-12-23T17:05:08.506107-05:00 ▶ [DEBU FUSE serve.go:853] 1c4 -> [ID=0x2f] Lookup 0x3 gen=0 valid=1m0s attr={valid=1s ino=5 size=0 mode=dr-x------}
2018-12-23T17:05:08.506989-05:00 ▶ [DEBU FUSE serve.go:787] 1c5 <- Read [ID=0x31 Node=0x2 Uid=1000 Gid=1000 Pid=5151] 0x2 4096 @0x20 dir=true fl=0 lock=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock
2018-12-23T17:05:08.507023-05:00 ▶ [DEBU FUSE serve.go:853] 1c6 -> [ID=0x31] Read 0
2018-12-23T17:05:08.507090-05:00 ▶ [DEBU FUSE serve.go:787] 1c7 <- Release [ID=0x32 Node=0x2 Uid=0 Gid=0 Pid=0] 0x1 fl=OpenReadOnly+OpenDirectory+OpenNonblock rfl=0 owner=0x0
2018-12-23T17:05:08.507121-05:00 ▶ [DEBU FUSE serve.go:853] 1c8 -> [ID=0x32] Release
2018-12-23T17:05:08.507219-05:00 ▶ [DEBU FUSE serve.go:787] 1c9 <- Read [ID=0x33 Node=0x2 Uid=1000 Gid=1000 Pid=5662] 0x3 4096 @0x20 dir=true fl=0 lock=0 ffl=OpenReadOnly+OpenDirectory+OpenNonblock
2018-12-23T17:05:08.507252-05:00 ▶ [DEBU FUSE serve.go:853] 1ca -> [ID=0x33] Read 0
2018-12-23T17:05:08.507303-05:00 ▶ [DEBU FUSE serve.go:787] 1cb <- Release [ID=0x34 Node=0x2 Uid=0 Gid=0 Pid=0] 0x2 fl=OpenReadOnly+OpenDirectory+OpenNonblock rfl=0 owner=0x0
2018-12-23T17:05:08.507320-05:00 ▶ [DEBU FUSE serve.go:853] 1cc -> [ID=0x34] Release
2018-12-23T17:05:08.508246-05:00 ▶ [DEBU FUSE serve.go:787] 1cd <- Release [ID=0x35 Node=0x2 Uid=0 Gid=0 Pid=0] 0x3 fl=OpenReadOnly+OpenDirectory+OpenNonblock rfl=0 owner=0x0
2018-12-23T17:05:08.508342-05:00 ▶ [DEBU FUSE serve.go:853] 1ce -> [ID=0x35] Release
Hi, I've noticed that kbfs has recently been taking about a minute to start up and make my files available when I start my system. This is the section of the logs from when I attempt to access my
private
folder (8:28:25) to when I actually get access (8:29:48).ls -l .local/share/keybase/fs/private
will hang during this time. I see a lot of ping timeouts, but I can ping other public sites successfully during this time. I've recently started using TunnelBear VPN, so I'm wondering if that could be related. I'll try with it disabled next time, though I use kbfs at work with a VPN and don't have this issue.