The gpg agent does not automatically start

[timthelion]

I tried following the instructions here and found that I could not use gpg. According to the instructions, all I have to do is initialize a key and set the GNUPGHOME env var. The instructions further read "The agent is automatically started if it isn't running when you run any gpg command." However, when I tried to use gpg I always got a message like:

timothy@yoga:~/foo[master] > echo "hi" | gpg2 --sign
gpg: Warning: not using 'Timothy Hobbs <timothy@hobbs.cz>' as default key: No secret key
gpg: all values passed to '--default-key' ignored
gpg: no default secret key: No secret key
gpg: signing failed: No secret key

After cding to the directory .gnupg/trezor and running the command ./run-agent.sh, I was able to use gpg as expected.

Here is my version information:

timothy@yoga:~/foo[master] > trezor-gpg --version
trezor-agent=0.9.2 libagent=0.11.2
timothy@yoga:~/foo[master] > gpg2 --version
gpg (GnuPG) 2.1.18
libgcrypt 1.7.6-beta
Copyright (C) 2017 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <https://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: /home/timothy/.gnupg/trezor
Supported algorithms:
Pubkey: RSA, ELG, DSA, ECDH, ECDSA, EDDSA
Cipher: IDEA, 3DES, CAST5, BLOWFISH, AES, AES192, AES256, TWOFISH,
        CAMELLIA128, CAMELLIA192, CAMELLIA256
Hash: SHA1, RIPEMD160, SHA256, SHA384, SHA512, SHA224
Compression: Uncompressed, ZIP, ZLIB, BZIP2

[romanz]

Thanks for reporting this issue!
It indeed seems that the agent fails to start correctly at the first invocation (before using run-agent.sh).
Could you please attach the trezor-gpg-agent log file, which hopefully may contain the reason for the initial starting up failures?

[timthelion]

I don't see any failures, I've attached the start of the log. Are you listening on dbus socket activation? How are you registering the service?

2018-04-18 10:27:22,694 DEBUG        sys.argv: ['/usr/local/bin/trezor-gpg-agent', '-vv', '--pin-entry-binary=pinentry', '--passphrase-entry-binary=pinentry', '--homedir', '/home/timothy/.gnupg/trezor', '--use-standard-socket', '--daemon'] [__init__.py:222]
2018-04-18 10:27:22,694 DEBUG        os.environ: environ({'DBUS_SESSION_BUS_ADDRESS': 'unix:path=/run/user/1000/bus', 'PATH': '/usr/local/go/bin:/home/timothy/bin:/home/timothy/.subuser/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games', 'GTK_MODULES': 'gail:atk-bridge', 'LANG': 'en_US.UTF-8', 'XAUTHORITY': '/home/timothy/.Xauthority', 'XDG_SEAT': 'seat0', 'WINDOWID': '15324191', 'QT_LINUX_ACCESSIBILITY_ALWAYS_ON': '1', 'USER': 'timothy', 'XDG_SESSION_ID': '6', 'QT4_IM_MODULE': 'xim', 'GPG_AGENT_INFO': '/run/user/1000/gnupg/S.gpg-agent:0:1', 'XDG_RUNTIME_DIR': '/run/user/1000', 'XDG_VTNR': '7', 'XDG_SEAT_PATH': '/org/freedesktop/DisplayManager/Seat0', 'PWD': '/', 'VTE_VERSION': '4601', 'XDG_CURRENT_DESKTOP': 'i3', 'LOGNAME': 'timothy', 'SHELL': '/usr/bin/fish', 'QT_ACCESSIBILITY': '1', 'HOME': '/home/timothy', 'SSH_AGENT_PID': '4641', 'LANGUAGE': 'en_US:en', 'XDG_SESSION_PATH': '/org/freedesktop/DisplayManager/Session1', 'DESKTOP_SESSION': 'i3', 'TERM': 'xterm-256color', 'LS_COLORS': 'rs=0:di=01;34:ln=01;36:mh=00:pi=40;33:so=01;35:do=01;35:bd=40;33;01:cd=40;33;01:or=40;31;01:mi=00:su=37;41:sg=30;43:ca=30;41:tw=30;42:ow=34;42:st=37;44:ex=01;32:*.tar=01;31:*.tgz=01;31:*.arc=01;31:*.arj=01;31:*.taz=01;31:*.lha=01;31:*.lz4=01;31:*.lzh=01;31:*.lzma=01;31:*.tlz=01;31:*.txz=01;31:*.tzo=01;31:*.t7z=01;31:*.zip=01;31:*.z=01;31:*.Z=01;31:*.dz=01;31:*.gz=01;31:*.lrz=01;31:*.lz=01;31:*.lzo=01;31:*.xz=01;31:*.zst=01;31:*.tzst=01;31:*.bz2=01;31:*.bz=01;31:*.tbz=01;31:*.tbz2=01;31:*.tz=01;31:*.deb=01;31:*.rpm=01;31:*.jar=01;31:*.war=01;31:*.ear=01;31:*.sar=01;31:*.rar=01;31:*.alz=01;31:*.ace=01;31:*.zoo=01;31:*.cpio=01;31:*.7z=01;31:*.rz=01;31:*.cab=01;31:*.jpg=01;35:*.jpeg=01;35:*.mjpg=01;35:*.mjpeg=01;35:*.gif=01;35:*.bmp=01;35:*.pbm=01;35:*.pgm=01;35:*.ppm=01;35:*.tga=01;35:*.xbm=01;35:*.xpm=01;35:*.tif=01;35:*.tiff=01;35:*.png=01;35:*.svg=01;35:*.svgz=01;35:*.mng=01;35:*.pcx=01;35:*.mov=01;35:*.mpg=01;35:*.mpeg=01;35:*.m2v=01;35:*.mkv=01;35:*.webm=01;35:*.ogm=01;35:*.mp4=01;35:*.m4v=01;35:*.mp4v=01;35:*.vob=01;35:*.qt=01;35:*.nuv=01;35:*.wmv=01;35:*.asf=01;35:*.rm=01;35:*.rmvb=01;35:*.flc=01;35:*.avi=01;35:*.fli=01;35:*.flv=01;35:*.gl=01;35:*.dl=01;35:*.xcf=01;35:*.xwd=01;35:*.yuv=01;35:*.cgm=01;35:*.emf=01;35:*.ogv=01;35:*.ogx=01;35:*.aac=00;36:*.au=00;36:*.flac=00;36:*.m4a=00;36:*.mid=00;36:*.midi=00;36:*.mka=00;36:*.mp3=00;36:*.mpc=00;36:*.ogg=00;36:*.ra=00;36:*.wav=00;36:*.oga=00;36:*.opus=00;36:*.spx=00;36:*.xspf=00;36:', 'XDG_GREETER_DATA_DIR': '/var/lib/lightdm/data/timothy', 'SHLVL': '1', 'COLORTERM': 'truecolor', 'DISPLAY': ':0.0', 'SSH_AUTH_SOCK': '/tmp/ssh-qKFNdhn7nh7Z/agent.4596', 'QT_IM_MODULE': 'ibus', 'GTK_IM_MODULE': 'xim', 'XDG_SESSION_DESKTOP': 'i3', 'XMODIFIERS': '@im=ibus', 'XDG_SESSION_TYPE': 'x11', 'CLUTTER_IM_MODULE': 'xim', 'GDMSESSION': 'i3', 'GDM_LANG': 'en_US.utf8'}) [__init__.py:223]
2018-04-18 10:27:22,695 DEBUG        pid: 27269, parent pid: 27268                                                                        [__init__.py:224]
2018-04-18 10:27:22,695 DEBUG        which 'gpgconf' => '/usr/bin/gpgconf'                                                                [util.py:230]
2018-04-18 10:27:22,695 DEBUG        calling ['/usr/bin/gpgconf', '--list-dirs'] with env {'GNUPGHOME': '/home/timothy/.gnupg/trezor'}    [keyring.py:19]
2018-04-18 10:27:22,697 DEBUG        output: b'sysconfdir:/etc/gnupg\nbindir:/usr/bin\nlibexecdir:/usr/lib/gnupg\nlibdir:/usr/lib/x86_64-linux-gnu/gnupg\ndatadir:/usr/share/gnupg\nlocaledir:/usr/share/locale\nsocketdir:/run/user/1000/gnupg/d.dkga3www73s7hzh1sq4yu5w6\ndirmngr-socket:/run/user/1000/gnupg/d.dkga3www73s7hzh1sq4yu5w6/S.dirmngr\nagent-ssh-socket:/run/user/1000/gnupg/d.dkga3www73s7hzh1sq4yu5w6/S.gpg-agent.ssh\nagent-extra-socket:/run/user/1000/gnupg/d.dkga3www73s7hzh1sq4yu5w6/S.gpg-agent.extra\nagent-browser-socket:/run/user/1000/gnupg/d.dkga3www73s7hzh1sq4yu5w6/S.gpg-agent.browser\nagent-socket:/run/user/1000/gnupg/d.dkga3www73s7hzh1sq4yu5w6/S.gpg-agent\nhomedir:/home/timothy/.gnupg/trezor\n' [keyring.py:21]
2018-04-18 10:27:22,698 DEBUG        ['/usr/bin/gpgconf', '--list-dirs']: {b'agent-socket': b'/run/user/1000/gnupg/d.dkga3www73s7hzh1sq4yu5w6/S.gpg-agent', b'agent-browser-socket': b'/run/user/1000/gnupg/d.dkga3www73s7hzh1sq4yu5w6/S.gpg-agent.browser', b'socketdir': b'/run/user/1000/gnupg/d.dkga3www73s7hzh1sq4yu5w6', b'localedir': b'/usr/share/locale', b'libexecdir': b'/usr/lib/gnupg', b'agent-extra-socket': b'/run/user/1000/gnupg/d.dkga3www73s7hzh1sq4yu5w6/S.gpg-agent.extra', b'homedir': b'/home/timothy/.gnupg/trezor', b'libdir': b'/usr/lib/x86_64-linux-gnu/gnupg', b'dirmngr-socket': b'/run/user/1000/gnupg/d.dkga3www73s7hzh1sq4yu5w6/S.dirmngr', b'sysconfdir': b'/etc/gnupg', b'agent-ssh-socket': b'/run/user/1000/gnupg/d.dkga3www73s7hzh1sq4yu5w6/S.gpg-agent.ssh', b'bindir': b'/usr/bin', b'datadir': b'/usr/share/gnupg'} [keyring.py:31]
2018-04-18 10:27:22,698 DEBUG        calling ['/usr/bin/gpgconf', '--list-components'] with env None                                      [keyring.py:19]
2018-04-18 10:27:22,700 DEBUG        output: b'gpg:OpenPGP:/usr/bin/gpg\ngpg-agent:Private Keys:/usr/bin/gpg-agent\nscdaemon:Smartcards:/usr/lib/gnupg/scdaemon\ngpgsm:S/MIME:/usr/bin/gpgsm\ndirmngr:Network:/usr/bin/dirmngr\npinentry:Passphrase Entry:/usr/bin/pinentry\n' [keyring.py:21]
2018-04-18 10:27:22,700 DEBUG        gpgconf --list-components: {'gpg-agent': '/usr/bin/gpg-agent', 'dirmngr': '/usr/bin/dirmngr', 'pinentry': '/usr/bin/pinentry', 'scdaemon': '/usr/lib/gnupg/scdaemon', 'gpgsm': '/usr/bin/gpgsm', 'gpg': '/usr/bin/gpg'} [keyring.py:196]
2018-04-18 10:27:22,701 DEBUG        calling ['/usr/bin/gpg', '--export'] with env {'GNUPGHOME': '/home/timothy/.gnupg/trezor'}           [keyring.py:19]
2018-04-18 10:27:22,704 DEBUG        output: b'\x98R\x04Z\xd7\x01=\x13\x08*\x86H\xce=\x03\x01\x07\x02\x03\x04m\xa3\x07\x0c\xa0E\xd0\x95\xd5Q\xa5\x11\xcd\xb9\x82\xff\x930\x02\xf4V\x7ft!\xed\x97\xe3\x93X\xca\x06{\x9f&\x03l\xca\xb5=\xfb\xe8\x91\x88n\x08d\xf8 \xe5%\xc4\x97\xea#+v\xbaK\xc4%\xa7\xd1_@\xb4 Timothy Hobbs <timothy@hobbs.cz>\x88\x80\x04\x13\x13\x08\x00\x1c\x05\x02Z\xd7\x01=\x02\x0b\t\x02\x1b\x03\x04\x15\x08\t\n\x04\x16\x02\x03\x01\x02\x17\x80\x02\x1e\x01\x00\x16\t\x10\x9c\xa9\xb3\xd7y\xce\xed\xe7\x0b\x1aTREZOR-GPG2Z\x00\xfd\x14\xdc\xf9\x8d\xed\xffG\xd2}\x07\x1c\xb5\xe6\xd9\xb7\x85\x84-\x81\x80\xb2\xce\xd5\xea\x98T/s\x82&\xf1\xd6\x00\xfc\x0fS\xb6\x97~\xb4\x14\x13\xbd\xd0\xd9f\x9b\\\xd8Z\x16?\x98 W\x90\xf3\xfb\xce\x85\xf7\xe8\x00\xa6\x11p\xb8V\x04Z\xd7\x01=\x12\x08*\x86H\xce=\x03\x01\x07\x02\x03\x04\xf7,\x88\xf3M\xbe#F\xb3\x178\xb4v\x12k\x94F\x8a\xd2\x00*\xbfG\x81\x16(\x7fs\xb0\xfb\x15i=d\xf4\xad\xf5d\x06w\x97\xfa\xd5&\x11@h\x9fg\xe3\xee\xe7P\x00\x9d\x15\x88Pdtv1\xcb%\x03\x01\x08\x07\x88m\x04\x18\x13\x08\x00\t\x05\x02Z\xd7\x01=\x02\x1b\x0c\x00\x16\t\x10\x9c\xa9\xb3\xd7y\xce\xed\xe7\x0b\x1aTREZOR-GPG\xd92\x00\xffg\x16\xf7\x1aI\x00\xad\xfc\xa4\x11\xc2\\\x17}\xea\xd3X\xdc\x05\xee\xe2\xce\xfa\x92L^A\x88$\xec\x89R\x00\xffT\x19\x11\xe5\xd0\xf2\x0e\x17\x18\x9c$[ \xa6V\xd0\x85\xe3\xa5}\x1a\xbd\x07\xaf\x9e\xb8\xed\xee\x0b\xa9D\t' [keyring.py:21]
2018-04-18 10:27:22,706 WARNING      no TTY found: Command '['tty']' returned non-zero exit status 1                                      [ui.py:59]
2018-04-18 10:27:22,706 INFO         using [b'display=:0.0'] for pinentry options                                                         [ui.py:67]
2018-04-18 10:27:22,706 DEBUG        serving on b'/run/user/1000/gnupg/d.dkga3www73s7hzh1sq4yu5w6/S.gpg-agent'                            [server.py:30]
2018-04-18 10:27:22,707 DEBUG        waiting for connection on /run/user/1000/gnupg/d.dkga3www73s7hzh1sq4yu5w6/S.gpg-agent                [agent.py:14]
2018-04-18 10:27:23,501 DEBUG        accepted connection on /run/user/1000/gnupg/d.dkga3www73s7hzh1sq4yu5w6/S.gpg-agent                   [agent.py:20]
2018-04-18 10:27:23,501 DEBUG        calling ['/usr/bin/gpg', '--version'] with env None                                                  [keyring.py:19]
2018-04-18 10:27:23,504 DEBUG        output: b'gpg (GnuPG) 2.1.18\nlibgcrypt 1.7.6-beta\nCopyright (C) 2017 Free Software Foundation, Inc.\nLicense GPLv3+: GNU GPL version 3 or later <https://gnu.org/licenses/gpl.html>\nThis is free software: you are free to change and redistribute it.\nThere is NO WARRANTY, to the extent permitted by law.\n\nHome: /home/timothy/.gnupg\nSupported algorithms:\nPubkey: RSA, ELG, DSA, ECDH, ECDSA, EDDSA\nCipher: IDEA, 3DES, CAST5, BLOWFISH, AES, AES192, AES256, TWOFISH,\n        CAMELLIA128, CAMELLIA192, CAMELLIA256\nHash: SHA1, RIPEMD160, SHA256, SHA384, SHA512, SHA224\nCompression: Uncompressed, ZIP, ZLIB, BZIP2\n' [keyring.py:21]
2018-04-18 10:27:23,505 DEBUG        <- b'OK'                                                                                             [keyring.py:53]
2018-04-18 10:27:23,505 DEBUG        -> b'RESET'                                                                                          [keyring.py:71]
2018-04-18 10:27:23,505 DEBUG        <- b'OK'                                                                                             [keyring.py:53]
2018-04-18 10:27:23,505 DEBUG        -> b'OPTION ttyname=/dev/pts/22'                                                                     [keyring.py:71]
2018-04-18 10:27:23,505 DEBUG        options: [b'ttyname=/dev/pts/22']                                                                    [agent.py:116]
2018-04-18 10:27:23,505 DEBUG        <- b'OK'                                                                                             [keyring.py:53]
2018-04-18 10:27:23,505 DEBUG        -> b'OPTION ttytype=xterm-256color'                                                                  [keyring.py:71]
2018-04-18 10:27:23,505 DEBUG        options: [b'ttyname=/dev/pts/22', b'ttytype=xterm-256color']                                         [agent.py:116]
2018-04-18 10:27:23,506 DEBUG        <- b'OK'                                                                                             [keyring.py:53]
2018-04-18 10:27:23,506 DEBUG        -> b'OPTION display=:0.0'                                                                            [keyring.py:71]
2018-04-18 10:27:23,506 DEBUG        options: [b'ttyname=/dev/pts/22', b'ttytype=xterm-256color', b'display=:0.0']                        [agent.py:116]
2018-04-18 10:27:23,506 DEBUG        <- b'OK'                                                                                             [keyring.py:53]
2018-04-18 10:27:23,506 DEBUG        -> b'OPTION xauthority=/home/timothy/.Xauthority'                                                    [keyring.py:71]
2018-04-18 10:27:23,506 DEBUG        options: [b'ttyname=/dev/pts/22', b'ttytype=xterm-256color', b'display=:0.0', b'xauthority=/home/timothy/.Xauthority'] [agent.py:116]
2018-04-18 10:27:23,506 DEBUG        <- b'OK'                                                                                             [keyring.py:53]
2018-04-18 10:27:23,506 DEBUG        -> b'OPTION putenv=XMODIFIERS=@im=ibus'                                                              [keyring.py:71]
2018-04-18 10:27:23,506 DEBUG        options: [b'ttyname=/dev/pts/22', b'ttytype=xterm-256color', b'display=:0.0', b'xauthority=/home/timothy/.Xauthority', b'putenv=XMODIFIERS=@im=ibus'] [agent.py:116]
2018-04-18 10:27:23,506 DEBUG        <- b'OK'                                                                                             [keyring.py:53]
2018-04-18 10:27:23,507 DEBUG        -> b'OPTION putenv=GTK_IM_MODULE=xim'                                                                [keyring.py:71]
2018-04-18 10:27:23,507 DEBUG        options: [b'ttyname=/dev/pts/22', b'ttytype=xterm-256color', b'display=:0.0', b'xauthority=/home/timothy/.Xauthority', b'putenv=XMODIFIERS=@im=ibus', b'putenv=GTK_IM_MODULE=xim'] [agent.py:116]
2018-04-18 10:27:23,507 DEBUG        <- b'OK'                                                                                             [keyring.py:53]
2018-04-18 10:27:23,507 DEBUG        -> b'OPTION putenv=DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus'                            [keyring.py:71]
2018-04-18 10:27:23,507 DEBUG        options: [b'ttyname=/dev/pts/22', b'ttytype=xterm-256color', b'display=:0.0', b'xauthority=/home/timothy/.Xauthority', b'putenv=XMODIFIERS=@im=ibus', b'putenv=GTK_IM_MODULE=xim', b'putenv=DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus'] [agent.py:116]
2018-04-18 10:27:23,507 DEBUG        <- b'OK'                                                                                             [keyring.py:53]
2018-04-18 10:27:23,507 DEBUG        -> b'OPTION putenv=QT_IM_MODULE=ibus'                                                                [keyring.py:71]
2018-04-18 10:27:23,507 DEBUG        options: [b'ttyname=/dev/pts/22', b'ttytype=xterm-256color', b'display=:0.0', b'xauthority=/home/timothy/.Xauthority', b'putenv=XMODIFIERS=@im=ibus', b'putenv=GTK_IM_MODULE=xim', b'putenv=DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus', b'putenv=QT_IM_MODULE=ibus'] [agent.py:116]
2018-04-18 10:27:23,507 DEBUG        <- b'OK'                                                                                             [keyring.py:53]
2018-04-18 10:27:23,507 DEBUG        -> b'OPTION lc-ctype=en_US.UTF-8'                                                                    [keyring.py:71]
2018-04-18 10:27:23,508 DEBUG        options: [b'ttyname=/dev/pts/22', b'ttytype=xterm-256color', b'display=:0.0', b'xauthority=/home/timothy/.Xauthority', b'putenv=XMODIFIERS=@im=ibus', b'putenv=GTK_IM_MODULE=xim', b'putenv=DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus', b'putenv=QT_IM_MODULE=ibus', b'lc-ctype=en_US.UTF-8'] [agent.py:116]
2018-04-18 10:27:23,508 DEBUG        <- b'OK'                                                                                             [keyring.py:53]
2018-04-18 10:27:23,508 DEBUG        -> b'OPTION lc-messages=en_US.UTF-8'                                                                 [keyring.py:71]
2018-04-18 10:27:23,508 DEBUG        options: [b'ttyname=/dev/pts/22', b'ttytype=xterm-256color', b'display=:0.0', b'xauthority=/home/timothy/.Xauthority', b'putenv=XMODIFIERS=@im=ibus', b'putenv=GTK_IM_MODULE=xim', b'putenv=DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus', b'putenv=QT_IM_MODULE=ibus', b'lc-ctype=en_US.UTF-8', b'lc-messages=en_US.UTF-8'] [agent.py:116]
2018-04-18 10:27:23,508 DEBUG        <- b'OK'                                                                                             [keyring.py:53]
2018-04-18 10:27:23,508 DEBUG        -> b'GETINFO version'                                                                                [keyring.py:71]
2018-04-18 10:27:23,508 DEBUG        <- b'D 2.1.18'                                                                                       [keyring.py:53]
2018-04-18 10:27:23,508 DEBUG        <- b'OK'                                                                                             [keyring.py:53]
2018-04-18 10:27:23,508 DEBUG        -> b'OPTION allow-pinentry-notify'                                                                   [keyring.py:71]
2018-04-18 10:27:23,508 DEBUG        options: [b'ttyname=/dev/pts/22', b'ttytype=xterm-256color', b'display=:0.0', b'xauthority=/home/timothy/.Xauthority', b'putenv=XMODIFIERS=@im=ibus', b'putenv=GTK_IM_MODULE=xim', b'putenv=DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus', b'putenv=QT_IM_MODULE=ibus', b'lc-ctype=en_US.UTF-8', b'lc-messages=en_US.UTF-8', b'allow-pinentry-notify'] [agent.py:116]
2018-04-18 10:27:23,508 DEBUG        <- b'OK'                                                                                             [keyring.py:53]
2018-04-18 10:27:23,508 DEBUG        -> b'OPTION agent-awareness=2.1.0'                                                                   [keyring.py:71]
2018-04-18 10:27:23,509 DEBUG        options: [b'ttyname=/dev/pts/22', b'ttytype=xterm-256color', b'display=:0.0', b'xauthority=/home/timothy/.Xauthority', b'putenv=XMODIFIERS=@im=ibus', b'putenv=GTK_IM_MODULE=xim', b'putenv=DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus', b'putenv=QT_IM_MODULE=ibus', b'lc-ctype=en_US.UTF-8', b'lc-messages=en_US.UTF-8', b'allow-pinentry-notify', b'agent-awareness=2.1.0'] [agent.py:116]
2018-04-18 10:27:23,509 DEBUG        <- b'OK'                                                                                             [keyring.py:53]
2018-04-18 10:27:23,509 DEBUG        -> b'HAVEKEY 7A47733D502C103EA5FBED863FB408E085271D61'                                               [keyring.py:71]
2018-04-18 10:27:23,509 DEBUG        prefix byte: 0b10011000                                                                              [decode.py:228]
2018-04-18 10:27:23,509 DEBUG        packet length: 82                                                                                    [decode.py:248]
2018-04-18 10:27:23,509 DEBUG        parsing elliptic curve key                                                                           [decode.py:149]
2018-04-18 10:27:23,509 DEBUG        mpi: 46da3070ca045d095d551a511cdb982ff933002f4567f7421ed97e39358ca067b9f26036ccab53dfbe891886e0864f820e525c497ea232b76ba4bc425a7d15f40 (515 bits) [decode.py:157]
2018-04-18 10:27:23,540 DEBUG        keygrip: 7A47733D502C103EA5FBED863FB408E085271D61                                                    [decode.py:169]
2018-04-18 10:27:23,540 DEBUG        key ID: 9CA9B3D779CEEDE7                                                                             [decode.py:186]
2018-04-18 10:27:23,541 DEBUG        packet "pubkey": {'algo': 19, 'created': 1524039997, '_to_hash': b'\x99\x00R\x04Z\xd7\x01=\x13\x08*\x86H\xce=\x03\x01\x07\x02\x03\x04m\xa3\x07\x0c\xa0E\xd0\x95\xd5Q\xa5\x11\xcd\xb9\x82\xff\x930\x02\xf4V\x7ft!\xed\x97\xe3\x93X\xca\x06{\x9f&\x03l\xca\xb5=\xfb\xe8\x91\x88n\x08d\xf8 \xe5%\xc4\x97\xea#+v\xbaK\xc4%\xa7\xd1_@', 'type': 'pubkey', 'version': 4, 'tag': 6, 'keygrip': b"zGs=P,\x10>\xa5\xfb\xed\x86?\xb4\x08\xe0\x85'\x1da", 'curve_oid': b'*\x86H\xce=\x03\x01\x07', 'key_id': b'\x9c\xa9\xb3\xd7y\xce\xed\xe7'} [decode.py:260]
2018-04-18 10:27:23,541 DEBUG        prefix byte: 0b10110100                                                                              [decode.py:228]
2018-04-18 10:27:23,541 DEBUG        packet length: 32                                                                                    [decode.py:248]
2018-04-18 10:27:23,541 DEBUG        packet "user_id": {'tag': 13, '_to_hash': b'\xb4\x00\x00\x00 Timothy Hobbs <timothy@hobbs.cz>', 'type': 'user_id', 'value': b'Timothy Hobbs <timothy@hobbs.cz>'} [decode.py:260]
2018-04-18 10:27:23,541 DEBUG        prefix byte: 0b10001000                                                                              [decode.py:228]
2018-04-18 10:27:23,541 DEBUG        packet length: 128                                                                                   [decode.py:248]
2018-04-18 10:27:23,541 DEBUG        packet "signature": {'tag': 2, 'hashed_subpackets': [b'\x02Z\xd7\x01=', b'\x0b\t', b'\x1b\x03', b'\x15\x08\t\n', b'\x16\x02\x03\x01', b'\x17\x80', b'\x1e\x01'], 'type': 'signature', 'version': 4, 'sig': (9436685687173432693433550198756857268743518602552498311160691040496063541718, 6932601237256093065308946460596564911517215329699595655596333681458557620592), 'unhashed_subpackets': [b'\x10\x9c\xa9\xb3\xd7y\xce\xed\xe7', b'\x1aTREZOR-GPG'], 'pubkey_alg': 19, 'sig_type': 19, 'hash_prefix': b'2Z', '_to_hash': b'\x04\x13\x13\x08\x00\x1c\x05\x02Z\xd7\x01=\x02\x0b\t\x02\x1b\x03\x04\x15\x08\t\n\x04\x16\x02\x03\x01\x02\x17\x80\x02\x1e\x01\x04\xff\x00\x00\x00"', 'hash_alg': 8} [decode.py:260]
2018-04-18 10:27:23,541 DEBUG        prefix byte: 0b10111000                                                                              [decode.py:228]
2018-04-18 10:27:23,541 DEBUG        packet length: 86                                                                                    [decode.py:248]
2018-04-18 10:27:23,541 DEBUG        parsing elliptic curve key                                                                           [decode.py:149]
2018-04-18 10:27:23,541 DEBUG        mpi: 4f72c88f34dbe2346b31738b476126b94468ad2002abf478116287f73b0fb15693d64f4adf564067797fad5261140689f67e3eee750009d15885064747631cb25 (515 bits) [decode.py:157]
2018-04-18 10:27:23,572 DEBUG        keygrip: 262C5916D9E2137CF736FEF4A6654F9D48349E45                                                    [decode.py:169]
2018-04-18 10:27:23,572 DEBUG        key ID: 7E2F7C6E41A3307C                                                                             [decode.py:186]
2018-04-18 10:27:23,572 DEBUG        packet "subkey": {'secret': b'', 'algo': 18, 'created': 1524039997, '_to_hash': b'\x99\x00V\x04Z\xd7\x01=\x12\x08*\x86H\xce=\x03\x01\x07\x02\x03\x04\xf7,\x88\xf3M\xbe#F\xb3\x178\xb4v\x12k\x94F\x8a\xd2\x00*\xbfG\x81\x16(\x7fs\xb0\xfb\x15i=d\xf4\xad\xf5d\x06w\x97\xfa\xd5&\x11@h\x9fg\xe3\xee\xe7P\x00\x9d\x15\x88Pdtv1\xcb%\x03\x01\x08\x07', 'type': 'subkey', 'version': 4, 'kdf': b'\x01\x08\x07', 'tag': 14, 'keygrip': b'&,Y\x16\xd9\xe2\x13|\xf76\xfe\xf4\xa6eO\x9dH4\x9eE', 'curve_oid': b'*\x86H\xce=\x03\x01\x07', 'key_id': b'~/|nA\xa30|'} [decode.py:260]
2018-04-18 10:27:23,572 DEBUG        prefix byte: 0b10001000                                                                              [decode.py:228]
2018-04-18 10:27:23,573 DEBUG        packet length: 109                                                                                   [decode.py:248]
2018-04-18 10:27:23,573 DEBUG        packet "signature": {'tag': 2, 'hashed_subpackets': [b'\x02Z\xd7\x01=', b'\x1b\x0c'], 'type': 'signature', 'version': 4, 'sig': (46628799479495909950814290136709075832174577269714555836729720636598666430802, 38038573983134050783566932323163326481293305479652399594307733578598199149577), 'unhashed_subpackets': [b'\x10\x9c\xa9\xb3\xd7y\xce\xed\xe7', b'\x1aTREZOR-GPG'], 'pubkey_alg': 19, 'sig_type': 24, 'hash_prefix': b'\xd92', '_to_hash': b'\x04\x18\x13\x08\x00\t\x05\x02Z\xd7\x01=\x02\x1b\x0c\x04\xff\x00\x00\x00\x0f', 'hash_alg': 8} [decode.py:260]
2018-04-18 10:27:23,573 DEBUG        parsed identity: {'host': '', 'port': None, 'user': None, 'proto': 'gpg', 'path': None}              [interface.py:30]
2018-04-18 10:27:23,822 DEBUG        Starting new HTTP connection (1): 127.0.0.1                                                          [connectionpool.py:212]
2018-04-18 10:27:23,824 DEBUG        http://127.0.0.1:21325 "POST /enumerate HTTP/1.1" 200 123                                            [connectionpool.py:400]
2018-04-18 10:27:23,835 DEBUG        transports: [<trezorlib.transport_bridge.BridgeTransport object at 0x7f2040ff6ba8>, <trezorlib.transport_hid.HidTransport object at 0x7f203fcfd9e8>] [trezor.py:102]
2018-04-18 10:27:23,836 DEBUG        Starting new HTTP connection (1): 127.0.0.1                                                          [connectionpool.py:212]
2018-04-18 10:27:23,838 DEBUG        http://127.0.0.1:21325 "POST /acquire/hid985ea66d893cfc370fcf282d39fd57a05c7a01e589773123fdce9b8d6e75390f/null HTTP/1.1" 200 18 [connectionpool.py:400]
2018-04-18 10:27:23,876 DEBUG        http://127.0.0.1:21325 "POST /call/123 HTTP/1.1" 200 1170                                            [connectionpool.py:400]
2018-04-18 10:27:23,880 DEBUG        http://127.0.0.1:21325 "POST /release/123 HTTP/1.1" 200 18                                           [connectionpool.py:400]
2018-04-18 10:27:23,880 DEBUG        connected to Trezor 79B09D790469D02E136B648B                                                         [trezor.py:82]
2018-04-18 10:27:23,880 DEBUG        label    : Tim's TREZOR                                                                              [trezor.py:83]
2018-04-18 10:27:23,881 DEBUG        vendor   : bitcointrezor.com                                                                         [trezor.py:84]
2018-04-18 10:27:23,881 DEBUG        version  : 1.6.0                                                                                     [trezor.py:88]
2018-04-18 10:27:23,881 DEBUG        revision : b'723cf295a72ce07b96047901bb8c2e461a2488f8'                                               [trezor.py:89]
2018-04-18 10:27:23,884 DEBUG        http://127.0.0.1:21325 "POST /acquire/hid985ea66d893cfc370fcf282d39fd57a05c7a01e589773123fdce9b8d6e75390f/null HTTP/1.1" 200 18 [connectionpool.py:400]
2018-04-18 10:27:23,889 DEBUG        http://127.0.0.1:21325 "POST /call/124 HTTP/1.1" 200 16                                              [connectionpool.py:400]
2018-04-18 10:27:23,892 DEBUG        http://127.0.0.1:21325 "POST /release/124 HTTP/1.1" 200 18                                           [connectionpool.py:400]
2018-04-18 10:27:23,892 DEBUG        identity parts: ['gpg://', 'Timothy Hobbs <timothy@hobbs.cz>']                                       [interface.py:46]
2018-04-18 10:27:23,892 DEBUG        "<gpg://Timothy Hobbs <timothy@hobbs.cz>|nist256p1>" getting public key (nist256p1) from Trezor      [trezor.py:128]
2018-04-18 10:27:23,892 DEBUG        identity parts: ['gpg://', 'Timothy Hobbs <timothy@hobbs.cz>']                                       [interface.py:46]
2018-04-18 10:27:23,893 DEBUG        bip32 address string: b'\x00\x00\x00\x00gpg://Timothy Hobbs <timothy@hobbs.cz>'                      [interface.py:88]
2018-04-18 10:27:23,895 DEBUG        http://127.0.0.1:21325 "POST /acquire/hid985ea66d893cfc370fcf282d39fd57a05c7a01e589773123fdce9b8d6e75390f/null HTTP/1.1" 200 18 [connectionpool.py:400]
2018-04-18 10:27:24,048 DEBUG        http://127.0.0.1:21325 "POST /call/125 HTTP/1.1" 200 12                                              [connectionpool.py:400]
2018-04-18 10:27:24,142 DEBUG        ['pinentry'] -> b'OK Pleased to meet you\n'                                                          [ui.py:85]
2018-04-18 10:27:24,142 DEBUG        ['pinentry'] <- b'SETTITLE Trezor passphrase\n'                                                      [ui.py:73]
2018-04-18 10:27:24,142 DEBUG        ['pinentry'] -> b'OK\n'                                                                              [ui.py:85]
2018-04-18 10:27:24,142 DEBUG        ['pinentry'] <- b'SETPROMPT Passphrase:\n'                                                           [ui.py:73]
2018-04-18 10:27:24,142 DEBUG        ['pinentry'] -> b'OK\n'                                                                              [ui.py:85]
2018-04-18 10:27:24,143 DEBUG        setting 12 options                                                                                   [ui.py:116]
2018-04-18 10:27:24,143 DEBUG        ['pinentry'] <- b'OPTION ttyname=/dev/pts/22\n'                                                      [ui.py:73]
2018-04-18 10:27:24,143 DEBUG        ['pinentry'] -> b'OK\n'                                                                              [ui.py:85]
2018-04-18 10:27:24,143 DEBUG        ['pinentry'] <- b'OPTION ttytype=xterm-256color\n'                                                   [ui.py:73]
2018-04-18 10:27:24,143 DEBUG        ['pinentry'] -> b'OK\n'                                                                              [ui.py:85]
2018-04-18 10:27:24,143 DEBUG        ['pinentry'] <- b'OPTION display=:0.0\n'                                                             [ui.py:73]
2018-04-18 10:27:24,143 DEBUG        ['pinentry'] -> b'OK\n'                                                                              [ui.py:85]
2018-04-18 10:27:24,143 DEBUG        ['pinentry'] <- b'OPTION xauthority=/home/timothy/.Xauthority\n'                                     [ui.py:73]
2018-04-18 10:27:24,144 DEBUG        ['pinentry'] -> b'ERR 83886254 Unknown option <Pinentry>\n'                                          [ui.py:85]
2018-04-18 10:27:24,144 DEBUG        ['pinentry'] <- b'OPTION putenv=XMODIFIERS=@im=ibus\n'                                               [ui.py:73]
2018-04-18 10:27:24,144 DEBUG        ['pinentry'] -> b'ERR 83886254 Unknown option <Pinentry>\n'                                          [ui.py:85]
2018-04-18 10:27:24,144 DEBUG        ['pinentry'] <- b'OPTION putenv=GTK_IM_MODULE=xim\n'                                                 [ui.py:73]
2018-04-18 10:27:24,144 DEBUG        ['pinentry'] -> b'ERR 83886254 Unknown option <Pinentry>\n'                                          [ui.py:85]
2018-04-18 10:27:24,144 DEBUG        ['pinentry'] <- b'OPTION putenv=DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus\n'             [ui.py:73]
2018-04-18 10:27:24,144 DEBUG        ['pinentry'] -> b'ERR 83886254 Unknown option <Pinentry>\n'                                          [ui.py:85]
2018-04-18 10:27:24,144 DEBUG        ['pinentry'] <- b'OPTION putenv=QT_IM_MODULE=ibus\n'                                                 [ui.py:73]
2018-04-18 10:27:24,144 DEBUG        ['pinentry'] -> b'ERR 83886254 Unknown option <Pinentry>\n'                                          [ui.py:85]
2018-04-18 10:27:24,144 DEBUG        ['pinentry'] <- b'OPTION lc-ctype=en_US.UTF-8\n'                                                     [ui.py:73]
2018-04-18 10:27:24,144 DEBUG        ['pinentry'] -> b'OK\n'                                                                              [ui.py:85]
2018-04-18 10:27:24,144 DEBUG        ['pinentry'] <- b'OPTION lc-messages=en_US.UTF-8\n'                                                  [ui.py:73]
2018-04-18 10:27:24,145 DEBUG        ['pinentry'] -> b'OK\n'                                                                              [ui.py:85]
2018-04-18 10:27:24,145 DEBUG        ['pinentry'] <- b'OPTION allow-pinentry-notify\n'                                                    [ui.py:73]
2018-04-18 10:27:24,145 DEBUG        ['pinentry'] -> b'ERR 83886254 Unknown option <Pinentry>\n'                                          [ui.py:85]
2018-04-18 10:27:24,145 DEBUG        ['pinentry'] <- b'OPTION agent-awareness=2.1.0\n'                                                    [ui.py:73]
2018-04-18 10:27:24,145 DEBUG        ['pinentry'] -> b'ERR 83886254 Unknown option <Pinentry>\n'                                          [ui.py:85]
2018-04-18 10:27:24,145 DEBUG        ['pinentry'] <- b'GETPIN\n'                                                                          [ui.py:73]
2018-04-18 10:27:26,531 DEBUG        ['pinentry'] -> '********'                                                                           [ui.py:85]
2018-04-18 10:27:26,774 DEBUG        http://127.0.0.1:21325 "POST /call/125 HTTP/1.1" 200 408                                             [connectionpool.py:400]
2018-04-18 10:27:26,777 DEBUG        http://127.0.0.1:21325 "POST /release/125 HTTP/1.1" 200 18                                           [connectionpool.py:400]
2018-04-18 10:27:26,778 DEBUG        result: <PublicKey: {'xpub': 'xpub6FYY5ZFxisVbE1m6PxMoHWrT8y3cCna94s4rL8ngc25QwmS4nXHsY37udxDQg1AeZAue2JnF4t9QVxEvxBQ12PExNem2k8dvcK4U3kAjYmw', 'node': <HDNodeType: {'fingerprint': 295032873, 'depth': 5, 'public_key': bytearray(b'\x02m\xa3\x07\x0c\xa0E\xd0\x95\xd5Q\xa5\x11\xcd\xb9\x82\xff\x930\x02\xf4V\x7ft!\xed\x97\xe3\x93X\xca\x06{'), 'chain_code': bytearray(b'\\\x07\xb0v\x0f\xc6\x8aE\xcf\xb7\x92YEg8\xbeO\x1bez\x8b\x9d;x\xbd\xbd\x84\xb5\xc2 \xde>'), 'child_num': 3159467424}>}> [trezor.py:132]
2018-04-18 10:27:26,811 DEBUG        <- b'OK'                                                                                             [keyring.py:53]
2018-04-18 10:27:26,812 DEBUG        waiting for connection on /run/user/1000/gnupg/d.dkga3www73s7hzh1sq4yu5w6/S.gpg-agent                [agent.py:14]
2018-04-18 10:27:26,824 DEBUG        accepted connection on /run/user/1000/gnupg/d.dkga3www73s7hzh1sq4yu5w6/S.gpg-agent                   [agent.py:20]
2018-04-18 10:27:26,824 DEBUG        calling ['/usr/bin/gpg', '--version'] with env None                                                  [keyring.py:19]
2018-04-18 10:27:26,827 DEBUG        output: b'gpg (GnuPG) 2.1.18\nlibgcrypt 1.7.6-beta\nCopyright (C) 2017 Free Software Foundation, Inc.\nLicense GPLv3+: GNU GPL version 3 or later <https://gnu.org/licenses/gpl.html>\nThis is free software: you are free to change and redistribute it.\nThere is NO WARRANTY, to the extent permitted by law.\n\nHome: /home/timothy/.gnupg\nSupported algorithms:\nPubkey: RSA, ELG, DSA, ECDH, ECDSA, EDDSA\nCipher: IDEA, 3DES, CAST5, BLOWFISH, AES, AES192, AES256, TWOFISH,\n        CAMELLIA128, CAMELLIA192, CAMELLIA256\nHash: SHA1, RIPEMD160, SHA256, SHA384, SHA512, SHA224\nCompression: Uncompressed, ZIP, ZLIB, BZIP2\n' [keyring.py:21]
2018-04-18 10:27:26,828 DEBUG        <- b'OK'                                                                                             [keyring.py:53]
2018-04-18 10:27:26,828 DEBUG        -> b'RESET'                                                                                          [keyring.py:71]
2018-04-18 10:27:26,828 DEBUG        <- b'OK'                                                                                             [keyring.py:53]
2018-04-18 10:27:26,828 DEBUG        -> b'OPTION ttyname=/dev/pts/22'                                                                     [keyring.py:71]
2018-04-18 10:27:26,829 DEBUG        options: [b'ttyname=/dev/pts/22']                                                                    [agent.py:116]
2018-04-18 10:27:26,829 DEBUG        <- b'OK'                                                                                             [keyring.py:53]
2018-04-18 10:27:26,829 DEBUG        -> b'OPTION lc-ctype=C'                                                                              [keyring.py:71]
2018-04-18 10:27:26,829 DEBUG        options: [b'ttyname=/dev/pts/22', b'lc-ctype=C']                                                     [agent.py:116]
2018-04-18 10:27:26,829 DEBUG        <- b'OK'                                                                                             [keyring.py:53]
2018-04-18 10:27:26,829 DEBUG        -> b'OPTION lc-messages=C'                                                                           [keyring.py:71]
2018-04-18 10:27:26,829 DEBUG        options: [b'ttyname=/dev/pts/22', b'lc-ctype=C', b'lc-messages=C']                                   [agent.py:116]
2018-04-18 10:27:26,829 DEBUG        <- b'OK'                                                                                             [keyring.py:53]
2018-04-18 10:27:26,830 DEBUG        -> b'GETINFO version'                                                                                [keyring.py:71]
2018-04-18 10:27:26,830 DEBUG        <- b'D 2.1.18'                                                                                       [keyring.py:53]
2018-04-18 10:27:26,830 DEBUG        <- b'OK'                                                                                             [keyring.py:53]
2018-04-18 10:27:26,830 DEBUG        -> b'OPTION allow-pinentry-notify'                                                                   [keyring.py:71]
2018-04-18 10:27:26,830 DEBUG        options: [b'ttyname=/dev/pts/22', b'lc-ctype=C', b'lc-messages=C', b'allow-pinentry-notify']         [agent.py:116]
2018-04-18 10:27:26,830 DEBUG        <- b'OK'                                                                                             [keyring.py:53]
2018-04-18 10:27:26,830 DEBUG        -> b'OPTION agent-awareness=2.1.0'                                                                   [keyring.py:71]
2018-04-18 10:27:26,830 DEBUG        options: [b'ttyname=/dev/pts/22', b'lc-ctype=C', b'lc-messages=C', b'allow-pinentry-notify', b'agent-awareness=2.1.0'] [agent.py:116]
2018-04-18 10:27:26,830 DEBUG        <- b'OK'                                                                                             [keyring.py:53]
2018-04-18 10:27:26,830 DEBUG        -> b'HAVEKEY 7A47733D502C103EA5FBED863FB408E085271D61 262C5916D9E2137CF736FEF4A6654F9D48349E45'      [keyring.py:71]
2018-04-18 10:27:26,831 DEBUG        prefix byte: 0b10011000                                                                              [decode.py:228]
2018-04-18 10:27:26,831 DEBUG        packet length: 82                                                                                    [decode.py:248]
2018-04-18 10:27:26,831 DEBUG        parsing elliptic curve key                                                                           [decode.py:149]
2018-04-18 10:27:26,831 DEBUG        mpi: 46da3070ca045d095d551a511cdb982ff933002f4567f7421ed97e39358ca067b9f26036ccab53dfbe891886e0864f820e525c497ea232b76ba4bc425a7d15f40 (515 bits) [decode.py:157]
2018-04-18 10:27:26,866 DEBUG        keygrip: 7A47733D502C103EA5FBED863FB408E085271D61                                                    [decode.py:169]
2018-04-18 10:27:26,866 DEBUG        key ID: 9CA9B3D779CEEDE7                                                                             [decode.py:186]
2018-04-18 10:27:26,866 DEBUG        packet "pubkey": {'algo': 19, 'created': 1524039997, '_to_hash': b'\x99\x00R\x04Z\xd7\x01=\x13\x08*\x86H\xce=\x03\x01\x07\x02\x03\x04m\xa3\x07\x0c\xa0E\xd0\x95\xd5Q\xa5\x11\xcd\xb9\x82\xff\x930\x02\xf4V\x7ft!\xed\x97\xe3\x93X\xca\x06{\x9f&\x03l\xca\xb5=\xfb\xe8\x91\x88n\x08d\xf8 \xe5%\xc4\x97\xea#+v\xbaK\xc4%\xa7\xd1_@', 'type': 'pubkey', 'version': 4, 'tag': 6, 'keygrip': b"zGs=P,\x10>\xa5\xfb\xed\x86?\xb4\x08\xe0\x85'\x1da", 'curve_oid': b'*\x86H\xce=\x03\x01\x07', 'key_id': b'\x9c\xa9\xb3\xd7y\xce\xed\xe7'} [decode.py:260]
2018-04-18 10:27:26,866 DEBUG        prefix byte: 0b10110100                                                                              [decode.py:228]
2018-04-18 10:27:26,867 DEBUG        packet length: 32                                                                                    [decode.py:248]
2018-04-18 10:27:26,867 DEBUG        packet "user_id": {'tag': 13, '_to_hash': b'\xb4\x00\x00\x00 Timothy Hobbs <timothy@hobbs.cz>', 'type': 'user_id', 'value': b'Timothy Hobbs <timothy@hobbs.cz>'} [decode.py:260]
2018-04-18 10:27:26,867 DEBUG        prefix byte: 0b10001000                                                                              [decode.py:228]
2018-04-18 10:27:26,867 DEBUG        packet length: 128                                                                                   [decode.py:248]
2018-04-18 10:27:26,867 DEBUG        packet "signature": {'tag': 2, 'hashed_subpackets': [b'\x02Z\xd7\x01=', b'\x0b\t', b'\x1b\x03', b'\x15\x08\t\n', b'\x16\x02\x03\x01', b'\x17\x80', b'\x1e\x01'], 'type': 'signature', 'version': 4, 'sig': (9436685687173432693433550198756857268743518602552498311160691040496063541718, 6932601237256093065308946460596564911517215329699595655596333681458557620592), 'unhashed_subpackets': [b'\x10\x9c\xa9\xb3\xd7y\xce\xed\xe7', b'\x1aTREZOR-GPG'], 'pubkey_alg': 19, 'sig_type': 19, 'hash_prefix': b'2Z', '_to_hash': b'\x04\x13\x13\x08\x00\x1c\x05\x02Z\xd7\x01=\x02\x0b\t\x02\x1b\x03\x04\x15\x08\t\n\x04\x16\x02\x03\x01\x02\x17\x80\x02\x1e\x01\x04\xff\x00\x00\x00"', 'hash_alg': 8} [decode.py:260]
2018-04-18 10:27:26,867 DEBUG        prefix byte: 0b10111000                                                                              [decode.py:228]
2018-04-18 10:27:26,867 DEBUG        packet length: 86                                                                                    [decode.py:248]
2018-04-18 10:27:26,867 DEBUG        parsing elliptic curve key                                                                           [decode.py:149]
2018-04-18 10:27:26,867 DEBUG        mpi: 4f72c88f34dbe2346b31738b476126b94468ad2002abf478116287f73b0fb15693d64f4adf564067797fad5261140689f67e3eee750009d15885064747631cb25 (515 bits) [decode.py:157]
2018-04-18 10:27:26,904 DEBUG        keygrip: 262C5916D9E2137CF736FEF4A6654F9D48349E45                                                    [decode.py:169]
2018-04-18 10:27:26,904 DEBUG        key ID: 7E2F7C6E41A3307C                                                                             [decode.py:186]
2018-04-18 10:27:26,904 DEBUG        packet "subkey": {'secret': b'', 'algo': 18, 'created': 1524039997, '_to_hash': b'\x99\x00V\x04Z\xd7\x01=\x12\x08*\x86H\xce=\x03\x01\x07\x02\x03\x04\xf7,\x88\xf3M\xbe#F\xb3\x178\xb4v\x12k\x94F\x8a\xd2\x00*\xbfG\x81\x16(\x7fs\xb0\xfb\x15i=d\xf4\xad\xf5d\x06w\x97\xfa\xd5&\x11@h\x9fg\xe3\xee\xe7P\x00\x9d\x15\x88Pdtv1\xcb%\x03\x01\x08\x07', 'type': 'subkey', 'version': 4, 'kdf': b'\x01\x08\x07', 'tag': 14, 'keygrip': b'&,Y\x16\xd9\xe2\x13|\xf76\xfe\xf4\xa6eO\x9dH4\x9eE', 'curve_oid': b'*\x86H\xce=\x03\x01\x07', 'key_id': b'~/|nA\xa30|'} [decode.py:260]
2018-04-18 10:27:26,904 DEBUG        prefix byte: 0b10001000                                                                              [decode.py:228]
2018-04-18 10:27:26,904 DEBUG        packet length: 109                                                                                   [decode.py:248]
2018-04-18 10:27:26,904 DEBUG        packet "signature": {'tag': 2, 'hashed_subpackets': [b'\x02Z\xd7\x01=', b'\x1b\x0c'], 'type': 'signature', 'version': 4, 'sig': (46628799479495909950814290136709075832174577269714555836729720636598666430802, 38038573983134050783566932323163326481293305479652399594307733578598199149577), 'unhashed_subpackets': [b'\x10\x9c\xa9\xb3\xd7y\xce\xed\xe7', b'\x1aTREZOR-GPG'], 'pubkey_alg': 19, 'sig_type': 24, 'hash_prefix': b'\xd92', '_to_hash': b'\x04\x18\x13\x08\x00\t\x05\x02Z\xd7\x01=\x02\x1b\x0c\x04\xff\x00\x00\x00\x0f', 'hash_alg': 8} [decode.py:260]
2018-04-18 10:27:26,904 DEBUG        parsed identity: {'host': '', 'port': None, 'user': None, 'proto': 'gpg', 'path': None}              [interface.py:30]
2018-04-18 10:27:26,906 DEBUG        Starting new HTTP connection (1): 127.0.0.1                                                          [connectionpool.py:212]
2018-04-18 10:27:26,908 DEBUG        http://127.0.0.1:21325 "POST /enumerate HTTP/1.1" 200 123                                            [connectionpool.py:400]
2018-04-18 10:27:26,911 DEBUG        transports: [<trezorlib.transport_bridge.BridgeTransport object at 0x7f203e0f7f60>, <trezorlib.transport_hid.HidTransport object at 0x7f203e0f7c18>] [trezor.py:102]
2018-04-18 10:27:26,912 DEBUG        Starting new HTTP connection (1): 127.0.0.1                                                          [connectionpool.py:212]
2018-04-18 10:27:26,914 DEBUG        http://127.0.0.1:21325 "POST /acquire/hid985ea66d893cfc370fcf282d39fd57a05c7a01e589773123fdce9b8d6e75390f/null HTTP/1.1" 200 18 [connectionpool.py:400]
2018-04-18 10:27:26,952 DEBUG        http://127.0.0.1:21325 "POST /call/126 HTTP/1.1" 200 1170                                            [connectionpool.py:400]
2018-04-18 10:27:26,956 DEBUG        http://127.0.0.1:21325 "POST /release/126 HTTP/1.1" 200 18                                           [connectionpool.py:400]
2018-04-18 10:27:26,956 DEBUG        connected to Trezor 79B09D790469D02E136B648B                                                         [trezor.py:82]
2018-04-18 10:27:26,956 DEBUG        label    : Tim's TREZOR                                                                              [trezor.py:83]
2018-04-18 10:27:26,956 DEBUG        vendor   : bitcointrezor.com                                                                         [trezor.py:84]
2018-04-18 10:27:26,957 DEBUG        version  : 1.6.0                                                                                     [trezor.py:88]
2018-04-18 10:27:26,957 DEBUG        revision : b'723cf295a72ce07b96047901bb8c2e461a2488f8'                                               [trezor.py:89]
2018-04-18 10:27:26,959 DEBUG        http://127.0.0.1:21325 "POST /acquire/hid985ea66d893cfc370fcf282d39fd57a05c7a01e589773123fdce9b8d6e75390f/null HTTP/1.1" 200 18 [connectionpool.py:400]
2018-04-18 10:27:26,965 DEBUG        http://127.0.0.1:21325 "POST /call/127 HTTP/1.1" 200 16                                              [connectionpool.py:400]
2018-04-18 10:27:26,968 DEBUG        http://127.0.0.1:21325 "POST /release/127 HTTP/1.1" 200 18                                           [connectionpool.py:400]
2018-04-18 10:27:26,969 DEBUG        identity parts: ['gpg://', 'Timothy Hobbs <timothy@hobbs.cz>']                                       [interface.py:46]
2018-04-18 10:27:26,969 DEBUG        "<gpg://Timothy Hobbs <timothy@hobbs.cz>|nist256p1>" getting public key (nist256p1) from Trezor      [trezor.py:128]
2018-04-18 10:27:26,969 DEBUG        identity parts: ['gpg://', 'Timothy Hobbs <timothy@hobbs.cz>']                                       [interface.py:46]
2018-04-18 10:27:26,969 DEBUG        bip32 address string: b'\x00\x00\x00\x00gpg://Timothy Hobbs <timothy@hobbs.cz>'                      [interface.py:88]
2018-04-18 10:27:26,972 DEBUG        http://127.0.0.1:21325 "POST /acquire/hid985ea66d893cfc370fcf282d39fd57a05c7a01e589773123fdce9b8d6e75390f/null HTTP/1.1" 200 18 [connectionpool.py:400]
2018-04-18 10:27:27,125 DEBUG        http://127.0.0.1:21325 "POST /call/128 HTTP/1.1" 200 12                                              [connectionpool.py:400]
2018-04-18 10:27:27,126 DEBUG        re-using cached Trezor passphrase                                                                    [trezor.py:60]
2018-04-18 10:27:27,367 DEBUG        http://127.0.0.1:21325 "POST /call/128 HTTP/1.1" 200 408                                             [connectionpool.py:400]
2018-04-18 10:27:27,370 DEBUG        http://127.0.0.1:21325 "POST /release/128 HTTP/1.1" 200 18                                           [connectionpool.py:400]
2018-04-18 10:27:27,371 DEBUG        result: <PublicKey: {'xpub': 'xpub6FYY5ZFxisVbE1m6PxMoHWrT8y3cCna94s4rL8ngc25QwmS4nXHsY37udxDQg1AeZAue2JnF4t9QVxEvxBQ12PExNem2k8dvcK4U3kAjYmw', 'node': <HDNodeType: {'fingerprint': 295032873, 'depth': 5, 'public_key': bytearray(b'\x02m\xa3\x07\x0c\xa0E\xd0\x95\xd5Q\xa5\x11\xcd\xb9\x82\xff\x930\x02\xf4V\x7ft!\xed\x97\xe3\x93X\xca\x06{'), 'chain_code': bytearray(b'\\\x07\xb0v\x0f\xc6\x8aE\xcf\xb7\x92YEg8\xbeO\x1bez\x8b\x9d;x\xbd\xbd\x84\xb5\xc2 \xde>'), 'child_num': 3159467424}>}> [trezor.py:132]
2018-04-18 10:27:27,404 DEBUG        <- b'OK'                                                                                             [keyring.py:53]
2018-04-18 10:27:27,404 DEBUG        -> b'KEYINFO 7A47733D502C103EA5FBED863FB408E085271D61'                                               [keyring.py:71]
2018-04-18 10:27:27,404 DEBUG        <- b"S KEYINFO b'7A47733D502C103EA5FBED863FB408E085271D61' X - - - - - - -"                          [keyring.py:53]
2018-04-18 10:27:27,404 DEBUG        <- b'OK'                                                                                             [keyring.py:53]
2018-04-18 10:27:27,405 DEBUG        -> b'KEYINFO 262C5916D9E2137CF736FEF4A6654F9D48349E45'                                               [keyring.py:71]
2018-04-18 10:27:27,405 DEBUG        <- b"S KEYINFO b'262C5916D9E2137CF736FEF4A6654F9D48349E45' X - - - - - - -"                          [keyring.py:53]
2018-04-18 10:27:27,405 DEBUG        <- b'OK'                                                                                             [keyring.py:53]
2018-04-18 10:27:27,406 DEBUG        waiting for connection on /run/user/1000/gnupg/d.dkga3www73s7hzh1sq4yu5w6/S.gpg-agent                [agent.py:14]
2018-04-18 11:52:51,224 DEBUG        sys.argv: ['/usr/local/bin/trezor-gpg-agent', '-vv', '--pin-entry-binary=pinentry', '--passphrase-entry-binary=pinentry'] [__init__.py:222]
2018-04-18 11:52:51,224 DEBUG        os.environ: environ({'XAUTHORITY': '/home/timothy/.Xauthority', 'XDG_SESSION_PATH': '/org/freedesktop/DisplayManager/Session5', 'DESKTOP_SESSION': 'i3', 'XDG_SEAT_PATH': '/org/freedesktop/DisplayManager/Seat0', 'GTK_MODULES': 'gail:atk-bridge', 'XDG_SEAT': 'seat0', 'LANGUAGE': 'en_US:en', 'PATH': '/usr/local/go/bin:/home/timothy/bin:/home/timothy/.subuser/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games', 'XDG_SESSION_ID': '18', 'CLUTTER_IM_MODULE': 'xim', 'WINDOWID': '14680067', 'DISPLAY': ':0.0', 'SSH_AGENT_PID': '12552', 'DBUS_SESSION_BUS_ADDRESS': 'unix:path=/run/user/1000/bus', 'XDG_VTNR': '7', 'USER': 'timothy', 'XDG_CURRENT_DESKTOP': 'i3', 'XDG_SESSION_DESKTOP': 'i3', 'QT_ACCESSIBILITY': '1', 'GDMSESSION': 'i3', 'VTE_VERSION': '4601', 'GNUPGHOME': '/home/timothy/.gnupg/trezor', 'PWD': '/home/timothy/.gnupg/trezor', 'XMODIFIERS': '@im=ibus', 'HOME': '/home/timothy', 'COLORTERM': 'truecolor', 'SHELL': '/usr/local/bin/fishlogin', 'XDG_RUNTIME_DIR': '/run/user/1000', 'GPG_AGENT_INFO': '/run/user/1000/gnupg/S.gpg-agent:0:1', 'QT_LINUX_ACCESSIBILITY_ALWAYS_ON': '1', 'SHLVL': '1', 'QT4_IM_MODULE': 'xim', 'TERM': 'xterm-256color', 'XDG_GREETER_DATA_DIR': '/var/lib/lightdm/data/timothy', 'GDM_LANG': 'en_US.utf8', 'XDG_SESSION_TYPE': 'x11', 'QT_IM_MODULE': 'ibus', 'LANG': 'en_US.UTF-8', 'LOGNAME': 'timothy', 'GTK_IM_MODULE': 'ibus', 'SSH_AUTH_SOCK': '/tmp/ssh-qROTCEyFo24h/agent.12507', 'LS_COLORS': 'rs=0:di=01;34:ln=01;36:mh=00:pi=40;33:so=01;35:do=01;35:bd=40;33;01:cd=40;33;01:or=40;31;01:mi=00:su=37;41:sg=30;43:ca=30;41:tw=30;42:ow=34;42:st=37;44:ex=01;32:*.tar=01;31:*.tgz=01;31:*.arc=01;31:*.arj=01;31:*.taz=01;31:*.lha=01;31:*.lz4=01;31:*.lzh=01;31:*.lzma=01;31:*.tlz=01;31:*.txz=01;31:*.tzo=01;31:*.t7z=01;31:*.zip=01;31:*.z=01;31:*.Z=01;31:*.dz=01;31:*.gz=01;31:*.lrz=01;31:*.lz=01;31:*.lzo=01;31:*.xz=01;31:*.zst=01;31:*.tzst=01;31:*.bz2=01;31:*.bz=01;31:*.tbz=01;31:*.tbz2=01;31:*.tz=01;31:*.deb=01;31:*.rpm=01;31:*.jar=01;31:*.war=01;31:*.ear=01;31:*.sar=01;31:*.rar=01;31:*.alz=01;31:*.ace=01;31:*.zoo=01;31:*.cpio=01;31:*.7z=01;31:*.rz=01;31:*.cab=01;31:*.jpg=01;35:*.jpeg=01;35:*.mjpg=01;35:*.mjpeg=01;35:*.gif=01;35:*.bmp=01;35:*.pbm=01;35:*.pgm=01;35:*.ppm=01;35:*.tga=01;35:*.xbm=01;35:*.xpm=01;35:*.tif=01;35:*.tiff=01;35:*.png=01;35:*.svg=01;35:*.svgz=01;35:*.mng=01;35:*.pcx=01;35:*.mov=01;35:*.mpg=01;35:*.mpeg=01;35:*.m2v=01;35:*.mkv=01;35:*.webm=01;35:*.ogm=01;35:*.mp4=01;35:*.m4v=01;35:*.mp4v=01;35:*.vob=01;35:*.qt=01;35:*.nuv=01;35:*.wmv=01;35:*.asf=01;35:*.rm=01;35:*.rmvb=01;35:*.flc=01;35:*.avi=01;35:*.fli=01;35:*.flv=01;35:*.gl=01;35:*.dl=01;35:*.xcf=01;35:*.xwd=01;35:*.yuv=01;35:*.cgm=01;35:*.emf=01;35:*.ogv=01;35:*.ogx=01;35:*.aac=00;36:*.au=00;36:*.flac=00;36:*.m4a=00;36:*.mid=00;36:*.midi=00;36:*.mka=00;36:*.mp3=00;36:*.mpc=00;36:*.ogg=00;36:*.ra=00;36:*.wav=00;36:*.oga=00;36:*.opus=00;36:*.spx=00;36:*.xspf=00;36:'}) [__init__.py:223]

[romanz]

Indeed, there is no error in the log...
Please let me know if this error reproduces.

How are you registering the service?

I am starting an ASSUAN-like server on ~/.gnupg/trezor/S.gpg-agent (UNIX domain socket), similar to GnuPG's gpg-agent behavior.
In order to connect to it, GNUPGHOME=~/.gnupg/trezor should be exported before using gpg.

[doolio]

Was this resolved? I seem to suffer the same issue.

[romanz]

Could you please open a new issue?

[doolio]

Sure.

[guiand888]

As of today, I also encounter this issue. Has there been a fix?

[doolio]

Sorry, I was to open a new issue. I still suffer from this. I will try to open a new issue this week with as much details as I can provide. A workaround for me as been to run the command ./run-agent.sh as described above.

[doolio]

Firstly, sorry for the late reply. I've investigated this issue further before opening a new issue. It turns out the issue for me was caused by the following line in my ~/.profile.

gpg-connect-agent updatestartuptty /bye >/dev/null

I believe this refreshes the TTY in case the user has switched into an X session. Perhaps @romanz understands why this would cause the trezor-gpg-agent from automatically starting. Could it be it starts the gpg-agent and this preventing the trezor-gpg-agent from starting?