search

keybase / client

Keybase Go Library, Client, Service, OS X, iOS, Android, Electron
BSD 3-Clause "New" or "Revised" License
8.9k stars 1.23k forks source link

"Unable to load KBFS" on MacBook Pro after High Sierra v10.13.5 update #12720

Open crackmac opened 6 years ago

crackmac commented 6 years ago

my log id: 941cfa52bce4bc8b1905101c

Status reports KBFS is running (see attached) keybase_status.txt

    status:    running
    version:   1.0.2-20180625190403+7df19ba7
    log:       /Users/myname/Library/Logs/keybase.kbfs.log
    mount:     /Volumes/Keybase (myname)

Uninstalling, Reboot, reinstalling (w/reboot) doesn't change anything

> key base uninstall
> rm -Rf /Applications/Keybase.app

I've gone through the Troubleshooting steps here with no noticeable difference. https://github.com/keybase/client/wiki/Troubleshooting#solutions

I've also removed and reinstalled FUSE for Mac OSX

crackmac commented 6 years ago

Update... after much trial and error I may have solved my issue.

I reinstalled FUSE from .dmg and enabled "MacFUSE compatibility layer" per https://github.com/osxfuse/osxfuse/wiki/FAQ#13-what-is-the-macfuse-compatibility-layer-do-i-need-it .

Rebooted and did the keybase uninstall reinstall dance again. After another reboot it appears the KBFS is able to do its thing.

I'm not 100% sure this is the solution and I don't have time to recreate (lost about .5 a day already) but if anyone else runs into the same issue please try the solution and post your results.

crackmac commented 6 years ago

Spoke a little too soon...

crackmac commented 6 years ago

New logID ba7463a29c429756bc1a211c

maxtaco commented 6 years ago 
 Error Domain=NSCocoaErrorDomain Code=513 "“Keybase (keduane)” couldn’t be removed because you don’t have permission to access it." UserInfo={NSFilePath=/Volumes/Keybase (keduane),

is there a permissions problem? Something owned as root in play?

cc @strib

crackmac commented 6 years ago

Not that I can see...

After a few uninstall/reboot/install cycles I do not see the KBFS error on launch of application or 088 Mounting the filesystem failed: exit status 2 error in the logs but I still am not able to view any of the files in subfolders of /keybase. I can see them in the keybase application files section but not locally.

Is there some way to test to see if FUSE or KBFS is healthy?

strib commented 6 years ago

@max that's usually a symptom of other failures, not the failure itself.

@crackmac I'm not near a mac at the moment to test this, but please try this from a terminal and let us know the output, to see if there are any useful error messages:

keybase --debug install -c fuse
crackmac commented 6 years ago

Thanks @strib

That looks like a fail

keybase --debug install -c fuse
2018-07-06T15:44:23.232417-07:00 ▶ [DEBU keybase globals.go:453] 001 Created Identify2Cache, max age: 5m0s
2018-07-06T15:44:23.232516-07:00 ▶ [DEBU keybase globals.go:456] 002 Created LinkCache, max size: 4000, clean dur: 1m0s
2018-07-06T15:44:23.232566-07:00 ▶ [DEBU keybase globals.go:458] 003 Created CardCache, max age: 5m0s
2018-07-06T15:44:23.232595-07:00 ▶ [DEBU keybase globals.go:476] 004 made a new full self cache
2018-07-06T15:44:23.232675-07:00 ▶ [DEBU keybase globals.go:478] 005 made a new cached UPAK loader (timeout=10m0s)
2018-07-06T15:44:23.236506-07:00 ▶ [DEBU keybase ui.go:604] 006 Setting GPG_TTY to /dev/ttys000
2018-07-06T15:44:23.236585-07:00 ▶ [DEBU keybase secret_store.go:144] 007 NewSecretStoreLocked: using os-specific SecretStore
2018-07-06T15:44:23.236981-07:00 ▶ [DEBU keybase globals.go:389] 008 Keybase CLI 2.1.2-20180625190314+836e4aeaca
2018-07-06T15:44:23.237003-07:00 ▶ [DEBU keybase globals.go:389] 009 - Built with go1.10.2
2018-07-06T15:44:23.237012-07:00 ▶ [DEBU keybase globals.go:389] 00a - Visit https://keybase.io for more details
2018-07-06T15:44:23.237682-07:00 ▶ [DEBU keybase main.go:212] 00b + configureProcesses
2018-07-06T15:44:23.237764-07:00 ▶ [DEBU keybase main.go:323] 00c + configureLogging
2018-07-06T15:44:23.237794-07:00 ▶ [DEBU keybase main.go:332] 00d Disabling log forwarding
2018-07-06T15:44:23.237848-07:00 ▶ [DEBU keybase main.go:325] 00e - configureLogging
2018-07-06T15:44:23.237914-07:00 ▶ [DEBU keybase main.go:214] 00f - configureProcesses -> <nil>
2018-07-06T15:44:23.238123-07:00 ▶ [DEBU keybase install_darwin.go:444] 010 Installing components: [fuse]
2018-07-06T15:44:23.238523-07:00 ▶ [INFO keybase app.go:106] 011 Installing KBFuse
2018-07-06T15:44:31.878071-07:00 ▶ [DEBU keybase app.go:77] 012 Output ([--debug --run-mode=prod --app-path=/Applications/Keybase.app --timeout=10 --install-fuse]): 07.06.2018 15:44:23.551 Installer:55[DEBG] Version: 1.1.61
07.06.2018 15:44:23.570 KBInstaller:27[DEBG] Installables: (
    "Privileged Helper",
    Fuse
)
07.06.2018 15:44:23.570 KBInstaller:32[DEBG] Install: Privileged Helper
07.06.2018 15:44:31.097 KBHelperTool:182[DEBG] Removing /Library/PrivilegedHelperTools/keybase.Helper
07.06.2018 15:44:31.097 KBHelperTool:191[DEBG] Installing helper tool via SMJobBless
07.06.2018 15:44:31.150 KBHelperTool:206[DEBG] Helper tool installed
07.06.2018 15:44:31.151 KBHelperTool:73[INFO] Connecting to keybase.Helper (privileged=1)
07.06.2018 15:44:31.151 KBHelperTool:73[INFO] Connected
07.06.2018 15:44:31.220 KBHelperTool:115[DEBG] Helper version: {
    build = 3;
    version = "1.0.31";
}
07.06.2018 15:44:31.225 KBInstaller:32[DEBG] Install: Fuse
07.06.2018 15:44:31.226 KBTask:114[DEBG] Task: /Applications/Keybase.app/Contents/SharedSupport/bin/keybase -d --log-format=file fuse status --bundle-version=3.6.3
07.06.2018 15:44:31.357 KBTask:55[DEBG] Task EOF
07.06.2018 15:44:31.357 KBTask:70[DEBG] Completed
07.06.2018 15:44:31.357 KBTask:72[DEBG] Task (err): 2018-07-06T15:44:31.244673-07:00 ▶ [DEBU keybase globals.go:453] 001 Created Identify2Cache, max age: 5m0s
2018-07-06T15:44:31.244749-07:00 ▶ [DEBU keybase globals.go:456] 002 Created LinkCache, max size: 4000, clean dur: 1m0s
2018-07-06T15:44:31.244773-07:00 ▶ [DEBU keybase globals.go:458] 003 Created CardCache, max age: 5m0s
2018-07-06T15:44:31.244787-07:00 ▶ [DEBU keybase globals.go:476] 004 made a new full self cache
2018-07-06T15:44:31.244840-07:00 ▶ [DEBU keybase globals.go:478] 005 made a new cached UPAK loader (timeout=10m0s)
2018-07-06T15:44:31.248509-07:00 ▶ [DEBU keybase ui.go:606] 006 Can't set GPG_TTY; discover failed
2018-07-06T15:44:31.248543-07:00 ▶ [DEBU keybase secret_store.go:144] 007 NewSecretStoreLocked: using os-specific SecretStore
2018-07-06T15:44:31.248567-07:00 ▶ [DEBU keybase globals.go:389] 008 Keybase CLI 2.1.2-20180625190314+836e4aeaca
2018-07-06T15:44:31.248579-07:00 ▶ [DEBU keybase globals.go:389] 009 - Built with go1.10.2
2018-07-06T15:44:31.248585-07:00 ▶ [DEBU keybase globals.go:389] 00a - Visit https://keybase.io for more details
2018-07-06T15:44:31.249355-07:00 ▶ [DEBU keybase main.go:212] 00b + configureProcesses
2018-07-06T15:44:31.249407-07:00 ▶ [DEBU keybase main.go:323] 00c + configureLogging
2018-07-06T15:44:31.249431-07:00 ▶ [DEBU keybase main.go:332] 00d Disabling log forwarding
2018-07-06T15:44:31.249445-07:00 ▶ [DEBU keybase main.go:325] 00e - configureLogging
2018-07-06T15:44:31.249472-07:00 ▶ [DEBU keybase main.go:214] 00f - configureProcesses -> <nil>
2018-07-06T15:44:31.250030-07:00 ▶ [DEBU keybase out_of_date.go:14] 010 + PrintOutOfDateWarnings
2018-07-06T15:44:31.250064-07:00 ▶ [DEBU keybase socket.go:65] 011 + GetSocket
2018-07-06T15:44:31.250100-07:00 ▶ [DEBU keybase rpc.go:25] 012 - GetSocket -> ok
2018-07-06T15:44:31.250113-07:00 ▶ [DEBU keybase socket.go:75] 013 | empty socket wrapper; need a new one
2018-07-06T15:44:31.250137-07:00 ▶ [DEBU keybase socket_nix.go:100] 014 + SocketInfo#dialSocket(unix:/Users/keduane/Library/Group Containers/keybase/Library/Caches/Keybase/keybased.sock)
2018-07-06T15:44:31.250158-07:00 ▶ [DEBU keybase socket_nix.go:124] 015 | net.Dial(unix:/Users/keduane/Library/Group Containers/keybase/Library/Caches/Keybase/keybased.sock)
2018-07-06T15:44:31.250508-07:00 ▶ [DEBU keybase socket_nix.go:125] 016 - SocketInfo#dialSocket(unix:/Users/keduane/Library/Group Containers/keybase/Library/Caches/Keybase/keybased.sock) -> ok
2018-07-06T15:44:31.250531-07:00 ▶ [DEBU keybase socket.go:90] 017 | DialSocket -> ok
2018-07-06T15:44:31.251438-07:00 ▶ [DEBU keybase out_of_date.go:28] 018 Got OutOfDateInfo: keybase1.OutOfDateInfo{UpgradeTo:"", UpgradeURI:"", CustomMessage:"", CriticalClockSkew:0}
2018-07-06T15:44:31.251460-07:00 ▶ [DEBU keybase out_of_date.go:44] 019 - PrintOutOfDateWarnings
2018-07-06T15:44:31.352898-07:00 ▶ [DEBU keybase globals.go:591] 01a GlobalContext#Shutdown(0xc420376000)
2018-07-06T15:44:31.353005-07:00 ▶ [DEBU keybase globals.go:635] 01b exiting shutdown code=0; err=<nil>

07.06.2018 15:44:31.357 KBTask:73[DEBG] Task (out): {
  "version": "",
  "bundleVersion": "3.6.3",
  "kextID": "",
  "path": "",
  "kextStarted": false,
  "installStatus": 2,
  "installAction": 4,
  "mountInfos": null,
  "status": {
    "code": 0,
    "name": "",
    "desc": "",
    "fields": null
  }
}

07.06.2018 15:44:31.375 KBFuseComponent:197[DEBG] Helper: kextInstall({
    destination = "/Library/Filesystems/kbfuse.fs";
    kextID = "com.github.kbfuse.filesystems.kbfuse";
    kextPath = "/Library/Filesystems/kbfuse.fs/Contents/Extensions/10.10/kbfuse.kext";
    source = "/Applications/Keybase.app/Contents/Resources/KeybaseInstaller.app/Contents/Resources/kbfuse.bundle";
})
07.06.2018 15:44:31.875 KBInstaller:45[INFO] Install complete
07.06.2018 15:44:31.875 KBInstaller:49[INFO] Privileged Helper: Installed, Bundle Version: 1.0.31
Version: 1.0.31
07.06.2018 15:44:31.875 KBInstaller:49[INFO] Fuse: Install Error: KextManager failed to load with status: -603946995
Not Installed, Bundle Version: 3.6.3
07.06.2018 15:44:31.875 Installer:95[INFO] Exit(1)
2018-07-06T15:44:31.878441-07:00 ▶ [ERRO keybase install_darwin.go:538] 013 Error installing KBFuse: exit status 1
crackmac commented 6 years ago

In my system preferences I show v3.8.0 FUSE for macOS installed. screen shot 2018-07-06 at 3 52 07 pm

strib commented 6 years ago

Fuse: Install Error: KextManager failed to load with status: -603946995

That seems to be an authentication error, maybe meaning that osx isn't allowing you to load the kext because you haven't explicitly allowed Keybase extensions yet: https://github.com/osxfuse/support/blob/master/load_osxfuse/fuse_kext.c#L92

@crackmac is your macOS distribution some kind of enterprise version? If so, I wonder if something like what is described in the "How This Affects Enterprise App Distribution" section here: https://developer.apple.com/library/archive/technotes/tn2459/_index.html

That is, booting into recovery and using the spctl kext-consent commands. One other use has reported the need to do this.

crackmac commented 6 years ago

That sounds like it could be relevant. This is my work computer and it occurred after doing a system update. I've disabled spctl kext-consent per the instructions above and reinstalled FUSE. that didn't resolve it yet but I'll jiggle the handle a bit longer and will get a fresh set of logs if still not working. Thank you!

strib commented 6 years ago

Ok thanks. Note that you don't need to install FUSE yourself, Keybase comes with its own version and own branded FUSE kernel extension, and doesn't use whatever you have installed on your system.

crackmac commented 6 years ago

Still working through this issue... approving the kernel extension is the right step but spctl kext-consent disable doesn't seem to be doing the trick. I'll try a few iterations of things and see if I can resolve.

The developer.apple.com doc linked above has some recommendations for handling this use case more gracefully...

https://developer.apple.com/library/archive/technotes/tn2459/_index.html#//apple_ref/doc/uid/DTS40017658-CH1-TNTAG3

How This Affects KEXT Developers

Installers and applications that load kernel extensions may need to be revised to gracefully handle the kernel extension failing to load. Many products treat a KEXT loading failure as a hard failure. Some prompt the user to reinstall, some present a cryptic error message, and some simply don't function.

Starting with macOS High Sierra, installers and apps that load KEXTs should expect that KEXT loading will fail if the user hasn't approved their KEXT. Instead of treating this as an error, the user should be informed that they may need to approve the KEXT.

To determine if a KEXT has failed to load because it does not have user approval:

If you are using kextutil or kextload, check for the exit code 27. In addition, kextutil will produce the error message System policy prevents loading the kernel extension. If you are using the KextManager APIs in IOKit/kext/KextManager.h, check for the result code kOSKextReturnSystemPolicy.

crackmac commented 6 years ago

Partially Resolved.

In my particular case and specific to MacOS High Sierra 10.13.x they are restricting some /Library and /System directories with SIP (Configure File System Protection). I can only get kbfs to startup without error if I disable SIP file stystem protection or completely. Some handy instructions here: https://www.cleverfiles.com/help/1013-sip/

Disabling third party kernel extension authorization (via https://developer.apple.com/library/archive/technotes/tn2459/_index.html) did not help in my case. I'm not sure why... maybe SIP trumps that.

I probably won't be able to keep SIP disabled forever so I'm wondering if there are any further suggestions.

Thanks for the help so far BTW.

strib commented 6 years ago

Thanks for the followup.

KBFS itself shouldn't require /Library or /System access, but it does make a directory under /Volumes, so if your particular enterprise distribution restricts that via SIP, that might be an issue. Our redirector process, to support multiple users on the same mac, also makes something in the root / directory.

If the problem is just with mountpoints, and not with the kernel extension itself (although our earlier debugging suggested that the kext was a problem), it might help to configure the mountpoint and disable the redirector. Instructions for that are here, under "Mountpoints": https://keybase.io/docs/kbfs/understanding_kbfs

Unfortunately, beyond that, I think I'm at the limit of my macOS kernel knowledge.

Also, as of today's release, the Finder integration isn't strictly necessary anymore. The Keybase GUI now supports both reading and uploading files. (This was also always possible on the CLI via the keybase fs command suite.) So if you find yourself unable to get the kext to work, you can always access KBFS through these other means, if needed.

crackmac commented 6 years ago

I don't think this is 'enterprise' related because the way I figured out what was going on was by comparing my work system with my personal Mac. I don't mean to disagree but KBFuse does generate some files in the /Library/StagedExtensions directory. I can confirm the files were not there before SIP was disabled and were created after SIP was disabled and Keybase app was started. I could reproduce and document better if that would be helpful.

> ls -la /Library/StagedExtensions/Library/Filesystems/kbfuse.fs/Contents/Extensions/10.10/kbfuse.kext/Contents/
total 8
drwxr-xr-x@ 5 root  wheel   160 Jun 25 12:09 ./
drwxr-xr-x@ 3 root  wheel    96 Jun 25 12:09 ../
-rwxr-xr-x@ 1 root  wheel  1529 Jun 25 12:09 Info.plist*
drwxr-xr-x@ 3 root  wheel    96 Jun 25 12:09 MacOS/
drwxr-xr-x@ 3 root  wheel    96 Jun 25 12:09 _CodeSignature/
strib commented 6 years ago

Ah ok thanks. I'm not familiar with what our kext does to set itself up, or what macOS does with third-party kexts when it verifies them, so you're probably right. I just meant that the Keybase code itself (excluding the kernel extension, which is osxfuse) doesn't touch those dirs. This sounds like a promising explanation.

I don't think this is 'enterprise' related because the way I figured out what was going on was by comparing my work system with my personal Mac.

I don't follow this. I thought the situation was that things worked on your personal mac, but didn't work on your work mac (which I was referring to as the 'enterprise' distribution). Do I have that backwards?

crackmac commented 6 years ago

Yeah... keybase was still working on my personal machine and I was using it to compare files and directories, permissions etc. My work machine stopped working after an upgrade to MacOS 10.13.x.

strib commented 6 years ago

Got it. That's why I was blaming it on some configuration specific to the distribution you're running on your work device. Could be wrong, but that's usually how SIP/kexts get locked down in that way, from what I can tell.