[ERRO keybase standard.go:225] 0ac GETPIN response didn't start with D; got "ERR 83918950 Inappropriate ioctl for device <Pinentry>" when decrypting

[bgpugh]

Whenever I try to decrypt from my pasteboard, I get:

2016-02-18T07:45:35.344280 ▶ [DEBU keybase pinentry.go:172] 09f - pinentryInstance::Init() -> <nil>
2016-02-18T07:45:35.344741 ▶ [DEBU keybase pinentry_osx.go:59] 0a0 | Error setting pinentry cache-id OPTION: Response to OPTION was ERR 83886254 Unknown option <Pinentry>
2016-02-18T07:45:35.344774 ▶ [DEBU keybase pinentry_osx.go:60] 0a1 | Not using secret store as a result.
2016-02-18T07:45:35.344856 ▶ [DEBU keybase pinentry.go:96] 0a2 - Pinentry::Get() -> GETPIN response didn't start with D; got "ERR 83918950 Inappropriate ioctl for device <Pinentry>"
2016-02-18T07:45:35.347009 ▶ [DEBU keybase log.go:30] 0a3 - PromptAndUnlock -> ERROR: GETPIN response didn't start with D; got "ERR 83918950 Inappropriate ioctl for device <Pinentry>"
2016-02-18T07:45:35.347230 ▶ [DEBU keybase log.go:30] 0a4 - GetSecretKeyAndSKBWithPrompt() -> ERROR: GETPIN response didn't start with D; got "ERR 83918950 Inappropriate ioctl for device <Pinentry>"
2016-02-18T07:45:35.347441 ▶ [DEBU keybase log.go:30] 0a5 - GetSecretKeyWithPrompt() -> ERROR: GETPIN response didn't start with D; got "ERR 83918950 Inappropriate ioctl for device <Pinentry>"
2016-02-18T07:45:35.347612 ▶ [DEBU keybase log.go:30] 0a6 - SaltpackDecrypt::Run -> ERROR: GETPIN response didn't start with D; got "ERR 83918950 Inappropriate ioctl for device <Pinentry>"
2016-02-18T07:45:35.347803 ▶ [DEBU keybase log.go:30] 0a7 - RunEngine(SaltpackDecrypt) -> ERROR: GETPIN response didn't start with D; got "ERR 83918950 Inappropriate ioctl for device <Pinentry>"
2016-02-18T07:45:35.452256 ▶ [DEBU keybase globals.go:252] 0a8 Calling shutdown first time through
2016-02-18T07:45:35.452433 ▶ [DEBU keybase login_state.go:944] 0a9 + Account "LoginState - Shutdown"
2016-02-18T07:45:35.452546 ▶ [DEBU keybase login_state.go:946] 0aa - Account "LoginState - Shutdown"
2016-02-18T07:45:35.452609 ▶ [DEBU keybase globals.go:295] 0ab exiting shutdown code=0; err=<nil>
2016-02-18T07:45:35.452669 ▶ [ERRO keybase standard.go:225] 0ac GETPIN response didn't start with D; got "ERR 83918950 Inappropriate ioctl for device <Pinentry>"

Full log attached: Inappropriate_ioctl.txt

[oconnor663]

Could you please do a keybase log send and give me the log ID it generates? Also please let me know how you installed gpg and pinentry (from homebrew?) and what versions they are. Finally, could you give me a description of how you're running the Keybase background service (did it start up automatically on boot, or did you start it explicitly in another terminal?) and the decrypt command itself (running it in a regular terminal, or something like tmux?)

Sorry for the spammy questions there. We've handled a lot of issues before about pinentry not being able to talk to your terminal, but they tend to be hard to track down. I'm afraid my only hope at debugging this will be to repro it myself, and to do that I might need to try to set a machine up exactly like yours.

[bgpugh]

Log ID: 6b84e7a16f79f60babe8d71c

gpg and pinentry are both installed via homebrew, and I also have pinentry-mac installed.

$ gpg --version && pinentry --version && pinentry-mac --version
gpg (GnuPG) 1.4.20
Copyright (C) 2015 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.

Home: ~/.gnupg
Supported algorithms:
Pubkey: RSA, RSA-E, RSA-S, ELG-E, DSA
Cipher: IDEA, 3DES, CAST5, BLOWFISH, AES, AES192, AES256, TWOFISH,
        CAMELLIA128, CAMELLIA192, CAMELLIA256
Hash: MD5, SHA1, RIPEMD160, SHA256, SHA384, SHA512, SHA224
Compression: Uncompressed, ZIP, ZLIB, BZIP2

pinentry-curses (pinentry) 0.9.7
Copyright (C) 2015 g10 Code GmbH
License GPLv2+: GNU GPL version 2 or later <http://gnu.org/licenses/>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.

pinentry-mac (pinentry) 0.9.4
Copyright (C) 2015 g10 Code GmbH
License GPLv2+: GNU GPL version 2 or later <http://gnu.org/licenses/>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.

In fact, I should be using pinentry-mac for my pinentry according to my gpg-agent.conf:

$ cat ~/.gnupg/gpg-agent.conf
enable-ssh-support
pinentry-program /usr/local/bin/pinentry-mac
default-cache-ttl 10800
max-cache-ttl 10800
use-standard-socket

keybase background service looks like it started on boot:

Local keybase keychain: locked
Session status:         no session

KBFS:
    status:    not running
    version:

Service:
    status:    running
    version:   1.0.13-0

The decrypt command I'm using is: pbpaste | keybase decrypt from a local terminal running zsh

[oconnor663]

Thanks! Digging...

[oconnor663]

Ok, I realize I asked you for the wrong logs, sorry about that. Could you please run pbpaste | keybase -d decrypt, and paste all the output from that somewhere for us? That should let us see more about what the client (as opposed to the daemon) is doing with your TTY.

[bgpugh]

It was already attached in the first report: https://github.com/keybase/keybase-issues/files/136471/Inappropriate_ioctl.txt

[oconnor663]

Ack you're totally right, my bad.

[oconnor663]

Ok a few more questions (thanks for putting up with all of this):

1. What's the output of tty in your terminal?
2. What's the output of /usr/local/bin/pinentry --version? (I'm trying to figure out whether that's referring to pinentry-curses or pinentry-mac.)

3. If you add the following lines to the top-level object in ~/.config/keybase/config.json, and then restart the daemon with keybase ctl restart, does it fix the problem?

   "pinentry": {
      "path": "/usr/local/bin/pinentry-mac"
   },

[bgpugh]

What's the output of tty in your terminal?

/dev/ttys000

What's the output of /usr/local/bin/pinentry --version?

pinentry-curses or pinentry-mac.)
pinentry-curses (pinentry) 0.9.7
Copyright (C) 2015 g10 Code GmbH
License GPLv2+: GNU GPL version 2 or later <http://gnu.org/licenses/>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.

If you add the following lines to the top-level object in ~/.config/keybase/config.json, and then restart the daemon with keybase ctl restart, does it fix the problem?

There is no ~/.config/keybase on my machine, but I placed it into ~/Library/Application\ Support/Keybase/config.json as so:

{
    "pinentry": {
        "path": "/usr/local/bin/pinentry-mac"
    },
    "current_user": ...

and now I get:

$ pbpaste | keybase -d decrypt
2016-02-24T00:22:34.231794 ▶ [DEBU keybase json.go:50] 001 + loading config file: ${HOME}/Library/Application Support/Keybase/config.json
2016-02-24T00:22:34.231951 ▶ [DEBU keybase json.go:78] 002 - successfully loaded config file
2016-02-24T00:22:34.232378 ▶ [DEBU keybase globals.go:224] 003 Created LinkCache, max size: 65536, clean dur: 1m0s
2016-02-24T00:22:34.234625 ▶ [DEBU keybase ui.go:477] 004 Can't set GPG_TTY; discover failed
2016-02-24T00:22:34.235095 ▶ [DEBU keybase globals.go:205] 005 Keybase CLI 1.0.13-0
2016-02-24T00:22:34.235166 ▶ [DEBU keybase globals.go:205] 006 - Built with go1.5.3
2016-02-24T00:22:34.235184 ▶ [DEBU keybase globals.go:205] 007 - Visit https://keybase.io for more details
2016-02-24T00:22:34.235220 ▶ [DEBU keybase main.go:125] 008 + configureProcesses
2016-02-24T00:22:34.235267 ▶ [DEBU keybase install_osx.go:515] 009 + AutoInstall for launchd
2016-02-24T00:22:34.235998 ▶ [DEBU keybase install_osx.go:528] 00a Using binPath: /usr/local/Cellar/keybase/1.0.13-0/bin/keybase
2016-02-24T00:22:34.236503 ▶ [DEBU keybase install_osx.go:517] 00b - AutoInstall -> false, <nil>
2016-02-24T00:22:34.236558 ▶ [DEBU keybase versionfix.go:59] 00c + FixVersionClash
2016-02-24T00:22:34.236596 ▶ [DEBU keybase socket_nix.go:23] 00d Dialing unix:${HOME}/Library/Caches/Keybase/keybased.sock
2016-02-24T00:22:34.236909 ▶ [DEBU keybase versionfix.go:65] 00e - FixVersionClash -> dial unix ${HOME}/Library/Caches/Keybase/keybased.sock: connect: no such file or directory
2016-02-24T00:22:34.236964 ▶ [DEBU keybase main.go:127] 00f - configureProcesses -> dial unix ${HOME}/Library/Caches/Keybase/keybased.sock: connect: no such file or directory
2016-02-24T00:22:34.338195 ▶ [DEBU keybase globals.go:252] 010 Calling shutdown first time through
2016-02-24T00:22:34.338276 ▶ [DEBU keybase login_state.go:944] 011 + Account "LoginState - Shutdown"
2016-02-24T00:22:34.338323 ▶ [DEBU keybase login_state.go:946] 012 - Account "LoginState - Shutdown"
2016-02-24T00:22:34.338343 ▶ [DEBU keybase globals.go:295] 013 exiting shutdown code=0; err=<nil>
2016-02-24T00:22:34.338389 ▶ [ERRO keybase standard.go:225] 014 dial unix ${HOME}/Library/Caches/Keybase/keybased.sock: connect: no such file or directory

When I try to restart the service a second time, I get a similar error:

$ keybase ctl restart
We found a Keybase service (homebrew.mxcl.keybase) but it's not running.
You might try starting it: keybase launchd start homebrew.mxcl.keybase

▶ ERROR dial unix /Users/bpugh/Library/Caches/Keybase/keybased.sock: connect: no such file or directory

$ keybase -d launchd start homebrew.mxcl.keybase
2016-02-24T00:23:05.494620 ▶ [DEBU keybase globals.go:224] 001 Created LinkCache, max size: 65536, clean dur: 1m0s
2016-02-24T00:23:05.496506 ▶ [DEBU keybase ui.go:475] 002 Setting GPG_TTY to /dev/ttys000
2016-02-24T00:23:05.496600 ▶ [DEBU keybase globals.go:205] 003 Keybase CLI 1.0.13-0
2016-02-24T00:23:05.496647 ▶ [DEBU keybase globals.go:205] 004 - Built with go1.5.3
2016-02-24T00:23:05.496665 ▶ [DEBU keybase globals.go:205] 005 - Visit https://keybase.io for more details
2016-02-24T00:23:05.496691 ▶ [DEBU keybase main.go:125] 006 + configureProcesses
2016-02-24T00:23:05.496721 ▶ [DEBU keybase main.go:221] 007 + configureLogging
2016-02-24T00:23:05.496777 ▶ [DEBU keybase main.go:230] 008 Disabling log forwarding
2016-02-24T00:23:05.496834 ▶ [DEBU keybase main.go:223] 009 - configureLogging
2016-02-24T00:23:05.496856 ▶ [DEBU keybase main.go:127] 00a - configureProcesses -> <nil>
2016-02-24T00:23:05.496990 ▶ [INFO keybase launchd.go:44] 00b Starting homebrew.mxcl.keybase
2016-02-24T00:23:05.603731 ▶ [DEBU keybase globals.go:252] 00c Calling shutdown first time through
2016-02-24T00:23:05.603812 ▶ [DEBU keybase login_state.go:944] 00d + Account "LoginState - Shutdown"
2016-02-24T00:23:05.603864 ▶ [DEBU keybase login_state.go:946] 00e - Account "LoginState - Shutdown"
2016-02-24T00:23:05.603891 ▶ [DEBU keybase globals.go:295] 00f exiting shutdown code=0; err=<nil>

[maxtaco]

But after that, is it working?

[maxtaco]

(you hit a bug that we've fix in which the restart command was broken on OSX)

(there's another bug that we've fixed in keybase config set so that it doesn't require restarts anymore).

But after you restarted via launchd, your problem should be fixed. Also, I noted that your terminal detection has started to work:

2016-02-24T00:23:05.496506 ▶ [DEBU keybase ui.go:475] 002 Setting GPG_TTY to /dev/ttys000

Were you running from inside of screen or tmux or something like it before?

[bgpugh]

After full reboot, it looks like everything is working again.

While reproducing, I'd never used screen nor tmux.