Extremely slow startup with VPN

[rcorre]

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.

2018-12-11T08:28:25.471646-05:00 ▶ [DEBU kbfs(kbfsfuse) tlf.go:75] 0d1 Loading root directory for folder rcorre (type: private, filter error: true) [tags:FID=DexvAR3Dh6xDeKFGZZvlYg]
2018-12-11T08:28:57.090763-05:00 ▶ [DEBU kbfs(BSR) bserver_remote.go:276] 0d2 BlockServerRemoteGet: Ping timeout -- reinitializing connection
2018-12-11T08:28:57.090938-05:00 ▶ [DEBU kbfs(BSR) connection.go:646] 0d3 (CONN BlockServerRemoteGet 19257556) Connection: getReconnectChan
2018-12-11T08:28:57.091010-05:00 ▶ [DEBU kbfs(BSR) connection.go:603] 0d4 (CONN BlockServerRemoteGet 19257556) Connection: waitForConnection; status: 3
2018-12-11T08:28:57.091070-05:00 ▶ [WARN kbfs(BSR) bserver_remote.go:244] 0d5 BlockServerRemoteGet: disconnected
2018-12-11T08:28:57.091284-05:00 ▶ [DEBU kbfs(BSR) connection.go:685] 0d6 (CONN BlockServerRemoteGet 19257556) starting random backoff: 8m37.39739699s
2018-12-11T08:28:57.381098-05:00 ▶ [DEBU kbfs(BSR) bserver_remote.go:276] 0d7 BlockServerRemotePut: Ping timeout -- reinitializing connection
2018-12-11T08:28:57.381264-05:00 ▶ [DEBU kbfs(BSR) connection.go:646] 0d8 (CONN BlockServerRemotePut 59429447) Connection: getReconnectChan
2018-12-11T08:28:57.381401-05:00 ▶ [DEBU kbfs(BSR) connection.go:603] 0d9 (CONN BlockServerRemotePut 59429447) Connection: waitForConnection; status: 3
2018-12-11T08:28:57.381464-05:00 ▶ [WARN kbfs(BSR) bserver_remote.go:244] 0da BlockServerRemotePut: disconnected
2018-12-11T08:28:57.381674-05:00 ▶ [DEBU kbfs(BSR) connection.go:685] 0db (CONN BlockServerRemotePut 59429447) starting random backoff: 34m25.768706418s
2018-12-11T08:29:17.091054-05:00 ▶ [INFO kbfs mdserver_remote.go:339] 0dc Ping timeout -- reinitializing connection
2018-12-11T08:29:17.091138-05:00 ▶ [DEBU kbfs connection.go:646] 0dd (CONN MDServerRemote 0828dc75) Connection: getReconnectChan
2018-12-11T08:29:17.091170-05:00 ▶ [DEBU kbfs connection.go:603] 0de (CONN MDServerRemote 0828dc75) Connection: waitForConnection; status: 3
2018-12-11T08:29:17.091195-05:00 ▶ [WARN kbfs mdserver_remote.go:403] 0df MDServerRemote is disconnected
2018-12-11T08:29:17.091379-05:00 ▶ [DEBU kbfs connection.go:685] 0e0 (CONN MDServerRemote 0828dc75) starting random backoff: 36m53.616644317s
2018-12-11T08:29:17.091393-05:00 ▶ [DEBU kbfs(RQ) rekey_queue.go:92] 0e1 Rekey queue background routine context done: {}
2018-12-11T08:29:25.474500-05:00 ▶ [DEBU kbfs journal_server.go:260] 0e2 Enabling a new journal for 08cc37586779e654ce0beaceba65e716 (enableAuto=true, set by user=false)
2018-12-11T08:29:25.474587-05:00 ▶ [DEBU kbfs journal_server.go:556] 0e3 Enabling journal for 08cc37586779e654ce0beaceba65e716 (Background work enabled)
2018-12-11T08:29:25.475309-05:00 ▶ [DEBU kbfs(TLFJ) tlf_journal.go:502] 0e4 Enabled journal for 08cc37586779e654ce0beaceba65e716 (stored bytes=0/files=0, available bytes=145997202022/files=5100000) with path /home/rcorre/.local/share/keybase/kbfs_journal/v1/012006ba01681f18bb2f58fe8bf235ae6c10-08cc37586779e654
2018-12-11T08:29:25.475413-05:00 ▶ [DEBU kbfs(kbfsfuse) dir.go:311] 0e6 TlfHandleChange called on "rcorre" [tags:FID=DexvAR3Dh6xDeKFGZZvlYg]
2018-12-11T08:29:25.475413-05:00 ▶ [DEBU kbfs(TLFJ) tlf_journal.go:589] 0e5 Waiting for the work signal for 08cc37586779e654ce0beaceba65e716 [tags:JID=BVfClpolDDkhj4WSwegV5w]
2018-12-11T08:29:25.475542-05:00 ▶ [DEBU kbfs(TLFJ) tlf_journal.go:594] 0e8 Got work signal for 08cc37586779e654ce0beaceba65e716 [tags:JID=BVfClpolDDkhj4WSwegV5w]
2018-12-11T08:29:25.475483-05:00 ▶ [DEBU kbfs kbfs_ops.go:631] 0e7 getMaybeCreateRootNode(/keybase/private/rcorre, , false) [tags:FID=DexvAR3Dh6xDeKFGZZvlYg]
2018-12-11T08:29:25.475593-05:00 ▶ [DEBU kbfs(TLFJ) tlf_journal.go:619] 0e9 Waiting for background work to be done for 08cc37586779e654ce0beaceba65e716 [tags:JID=CcJoeH9q7B1uk5F_OcyBRA]
2018-12-11T08:29:25.475627-05:00 ▶ [DEBU kbfs(TLFJ) tlf_journal.go:885] 0ea Nothing else to flush [tags:JID=BVfClpolDDkhj4WSwegV5w]
2018-12-11T08:29:25.475835-05:00 ▶ [DEBU kbfs(TLFJ) tlf_journal.go:949] 0eb Flushed 0 block entries and 0 MD entries for 08cc37586779e654ce0beaceba65e716 [tags:JID=BVfClpolDDkhj4WSwegV5w]
2018-12-11T08:29:25.475897-05:00 ▶ [DEBU kbfs(TLFJ) tlf_journal.go:589] 0ec Waiting for the work signal for 08cc37586779e654ce0beaceba65e716 [tags:JID=2-sL_usLE4ILxcROwwRkBw]
2018-12-11T08:29:27.091219-05:00 ▶ [DEBU kbfs(BSR) bserver_remote.go:279] 0ed reconnect error: context deadline exceeded
2018-12-11T08:29:27.091360-05:00 ▶ [DEBU kbfs(BSR) pinger.go:71] 0ee BlockServerRemoteGet: stopping ping ticker
2018-12-11T08:29:27.381473-05:00 ▶ [DEBU kbfs(BSR) bserver_remote.go:279] 0ef reconnect error: context deadline exceeded
2018-12-11T08:29:27.381643-05:00 ▶ [DEBU kbfs(BSR) pinger.go:71] 0f0 BlockServerRemotePut: stopping ping ticker
2018-12-11T08:29:47.091295-05:00 ▶ [INFO kbfs mdserver_remote.go:341] 0f1 reconnect error: context deadline exceeded
2018-12-11T08:29:47.091310-05:00 ▶ [DEBU kbfs(ECQU-KBFSOps) fetch_decider.go:116] 0f2 Blocking on fetch; cached data is 1m29.564740986s old
2018-12-11T08:29:47.091491-05:00 ▶ [DEBU kbfs(ECQU-KBFSOps) fetch_decider.go:67] 0f4 Spawning fetch in background with tag:ECQU=n6gZWCrTlq9WshQspH4BEw
2018-12-11T08:29:47.091530-05:00 ▶ [DEBU kbfs connection.go:689] 0f5 (CONN MDServerRemote 0828dc75) backoff done!
2018-12-11T08:29:47.091562-05:00 ▶ [DEBU kbfs connection.go:494] 0f7 (CONN MDServerRemote 0828dc75) Connection: dialing transport
2018-12-11T08:29:47.091436-05:00 ▶ [INFO kbfs mdserver_remote.go:348] 0f3 MDServerRemote: ping error context canceled
2018-12-11T08:29:47.091675-05:00 ▶ [DEBU kbfs pinger.go:71] 0f9 MDServerRemote: stopping ping ticker
2018-12-11T08:29:47.091631-05:00 ▶ [DEBU kbfs(BSR) connection.go:689] 0f8 (CONN BlockServerRemoteGet 19257556) backoff done!
2018-12-11T08:29:47.091714-05:00 ▶ [DEBU kbfs(BSR) connection.go:494] 0fa (CONN BlockServerRemoteGet 19257556) Connection: dialing transport
2018-12-11T08:29:47.091534-05:00 ▶ [DEBU kbfs kbfs_ops.go:968] 0f6 Getting quota usage error: context deadline exceeded
2018-12-11T08:29:47.091834-05:00 ▶ [DEBU kbfs connection.go:218] 0fb (CONNTSPT 5ecc4f90) Dialing mdserver-1.kbfs.keybaseapi.com:443
2018-12-11T08:29:47.091848-05:00 ▶ [WARN kbfs(kbfsfuse) remote_status.go:63] 0fc KBFS Status failed: { false 0 0 0 0 0 0 map[] <nil> map[]},0xc000603f80,context deadline exceeded
2018-12-11T08:29:47.092136-05:00 ▶ [DEBU kbfs(kbfsfuse) fs.go:336] 0fe User changed: "rcorre" -> ""
2018-12-11T08:29:47.092194-05:00 ▶ [DEBU kbfs(kbfsfuse) dir.go:311] 0ff TlfHandleChange called on "(nil)"
2018-12-11T08:29:47.092055-05:00 ▶ [DEBU kbfs(BSR) connection.go:218] 0fd (CONNTSPT 4785e1b8) Dialing bserver-0.kbfs.keybaseapi.com:443
2018-12-11T08:29:47.417373-05:00 ▶ [DEBU kbfs connection.go:239] 100 (CONNTSPT 5ecc4f90) baseConn: 172.18.12.62:54010; Calling Handshake
2018-12-11T08:29:47.427742-05:00 ▶ [DEBU kbfs(BSR) connection.go:239] 101 (CONNTSPT 4785e1b8) baseConn: 172.18.12.62:59980; Calling Handshake
2018-12-11T08:29:47.788837-05:00 ▶ [DEBU kbfs(BSR) connection.go:246] 102 (CONNTSPT 4785e1b8) Handshaken
2018-12-11T08:29:47.789271-05:00 ▶ [DEBU kbfs(BSR) connection.go:514] 103 (CONN BlockServerRemoteGet 19257556) Connection: calling OnConnect
2018-12-11T08:29:47.789528-05:00 ▶ [DEBU kbfs(BSR) connection.go:646] 104 (CONN BlockServerRemoteGet 19257556) Connection: getReconnectChan
2018-12-11T08:29:47.789629-05:00 ▶ [DEBU kbfs(BSR) connection.go:603] 105 (CONN BlockServerRemoteGet 19257556) Connection: waitForConnection; status: 1
2018-12-11T08:29:47.789933-05:00 ▶ [DEBU kbfs connection.go:246] 106 (CONNTSPT 5ecc4f90) Handshaken
2018-12-11T08:29:47.790399-05:00 ▶ [DEBU kbfs connection.go:514] 107 (CONN MDServerRemote 0828dc75) Connection: calling OnConnect
2018-12-11T08:29:47.790493-05:00 ▶ [INFO kbfs mdserver_remote.go:199] 108 OnConnect called with a new connection
2018-12-11T08:29:47.790515-05:00 ▶ [DEBU kbfs connection.go:646] 109 (CONN MDServerRemote 0828dc75) Connection: getReconnectChan
2018-12-11T08:29:47.790763-05:00 ▶ [DEBU kbfs connection.go:603] 10a (CONN MDServerRemote 0828dc75) Connection: waitForConnection; status: 1
2018-12-11T08:29:47.964152-05:00 ▶ [DEBU kbfs crypto_client.go:98] 10b Signing 423-byte message to string
2018-12-11T08:29:47.965482-05:00 ▶ [DEBU kbfs mdserver_remote.go:260] 10c received challenge
2018-12-11T08:29:47.965643-05:00 ▶ [DEBU kbfs crypto_client.go:112] 10d Signed 423-byte message: err=<nil>
2018-12-11T08:29:47.965660-05:00 ▶ [DEBU kbfs crypto_client.go:98] 10e Signing 421-byte message to string
2018-12-11T08:29:47.966980-05:00 ▶ [DEBU kbfs crypto_client.go:112] 10f Signed 421-byte message: err=<nil>
2018-12-11T08:29:47.967091-05:00 ▶ [DEBU kbfs mdserver_remote.go:269] 110 authentication token signed
2018-12-11T08:29:48.129095-05:00 ▶ [DEBU kbfs(BSR) bserver_remote.go:186] 111 BlockServerRemote: resetAuth called, err: <nil>
2018-12-11T08:29:48.129189-05:00 ▶ [DEBU kbfs(BSR) pinger.go:51] 112 BlockServerRemoteGet: Starting new ping ticker with interval 10
2018-12-11T08:29:48.129245-05:00 ▶ [DEBU kbfs(BSR) connection.go:532] 113 (CONN BlockServerRemoteGet 19257556) Connection: connected
2018-12-11T08:29:48.152948-05:00 ▶ [INFO kbfs mdserver_remote.go:277] 114 authentication successful; ping interval: 30s

[strib]

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.

[rcorre]

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.

[strib]

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!

[rcorre]

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.

[rcorre]

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