Closed galuszkak closed 6 years ago
Thanks for reporting this issue!
It may be related to https://github.com/romanz/trezor-agent/issues/98#issuecomment-284366380.
Are you using the latest hidapi
package?
$ pip3 freeze | grep hidapi
hidapi==0.7.99.post21
BTW @romanz thanks, for putting so much hard work in those MacOS bugs that I'm just throwing at You. Really BIG thanks for Your help, commitment 👍 and kindness. I hope when we resolve most of those then I create homebrew package so anyone can benefit from this hard work from You :).
No problem, I am happy to help :)
Could you reproduce the segfault when running the trezor-agent
with highest verbosity level (using the trezor-agent kamil@example.com -vv -s
command)?
This way, we can see the individual requests sent to the device, and hopefully this will help debugging the failure...
First answer is:
% pip3 freeze|grep hidapi
hidapi==0.7.99.post21
And debug log is:
kamil@Kamils-MacBook-Pro:~/Projects/example % git fetch
2017-10-25 09:52:46,870 DEBUG welcome agent [server.py:53]
2017-10-25 09:52:46,870 DEBUG request: 1 bytes [protocol.py:94]
2017-10-25 09:52:46,871 DEBUG calling list_pubs() [protocol.py:102]
2017-10-25 09:52:46,871 DEBUG loading SSH public key: 'ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBPV2v9GXM1FK+JZRwPqB3rKFA/bl9p4qX/x/E/A2Ya2kuwaFpPM/hOSXn+gMT8L/c9ZL2M5z9QXT0mbuRGA7xKg= <ssh://kamil@example.com|nist256p1>\n' [formats.py:192]
2017-10-25 09:52:46,871 DEBUG waiting for connection on /var/folders/h6/94cjw0j97g59d_w5wmwhcyl80000gn/T/trezor-ssh-agent-r6inie9j [server.py:92]
2017-10-25 09:52:46,871 DEBUG key type: b'ecdsa-sha2-nistp256' [formats.py:55]
2017-10-25 09:52:46,871 DEBUG curve name: b'nistp256' [formats.py:62]
2017-10-25 09:52:46,871 DEBUG loaded ecdsa-sha2-nistp256 public key: ab:0c:37:53:aa:b4:26:a7:c0:5b:6c:37:1b:a2:fa:32 [formats.py:198]
2017-10-25 09:52:46,871 DEBUG available keys: [b'<ssh://kamil@example.com|nist256p1>'] [protocol.py:114]
2017-10-25 09:52:46,871 DEBUG 1) ab:0c:37:53:aa:b4:26:a7:c0:5b:6c:37:1b:a2:fa:32 [protocol.py:116]
2017-10-25 09:52:46,871 DEBUG reply: 157 bytes [protocol.py:105]
2017-10-25 09:52:48,011 DEBUG request: 324 bytes [protocol.py:94]
2017-10-25 09:52:48,011 DEBUG calling sign_message() [protocol.py:102]
2017-10-25 09:52:48,011 DEBUG key type: b'ecdsa-sha2-nistp256' [formats.py:55]
2017-10-25 09:52:48,011 DEBUG curve name: b'nistp256' [formats.py:62]
2017-10-25 09:52:48,011 DEBUG looking for ab:0c:37:53:aa:b4:26:a7:c0:5b:6c:37:1b:a2:fa:32 [protocol.py:128]
2017-10-25 09:52:48,011 DEBUG loading SSH public key: 'ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBPV2v9GXM1FK+JZRwPqB3rKFA/bl9p4qX/x/E/A2Ya2kuwaFpPM/hOSXn+gMT8L/c9ZL2M5z9QXT0mbuRGA7xKg= <ssh://kamil@example.com|nist256p1>\n' [formats.py:192]
2017-10-25 09:52:48,011 DEBUG key type: b'ecdsa-sha2-nistp256' [formats.py:55]
2017-10-25 09:52:48,011 DEBUG curve name: b'nistp256' [formats.py:62]
2017-10-25 09:52:48,012 DEBUG loaded ecdsa-sha2-nistp256 public key: ab:0c:37:53:aa:b4:26:a7:c0:5b:6c:37:1b:a2:fa:32 [formats.py:198]
2017-10-25 09:52:48,012 DEBUG using key b'<ssh://kamil@example.com|nist256p1>' (ab:0c:37:53:aa:b4:26:a7:c0:5b:6c:37:1b:a2:fa:32) [protocol.py:135]
2017-10-25 09:52:48,012 DEBUG signing 207-byte blob with "<ssh://kamil@example.com|nist256p1>" key [protocol.py:142]
2017-10-25 09:52:48,012 DEBUG key type: b'ecdsa-sha2-nistp256' [formats.py:55]
2017-10-25 09:52:48,012 DEBUG curve name: b'nistp256' [formats.py:62]
2017-10-25 09:52:48,012 DEBUG b'ssh-connection': user b'git' via b'publickey' (b'ecdsa-sha2-nistp256') [client.py:38]
2017-10-25 09:52:48,012 DEBUG nonce: b"+\xaeC\xd0N>\xbe\xb9\x86\xd2'\x10\xed\xc9\x92\xc45\xb4\xa9\x95\xfe\xce\xfe;\xe2i_VfXJ\xd6" [client.py:39]
2017-10-25 09:52:48,012 DEBUG fingerprint: ab:0c:37:53:aa:b4:26:a7:c0:5b:6c:37:1b:a2:fa:32 [client.py:41]
2017-10-25 09:52:48,012 DEBUG hidden challenge size: 207 bytes [client.py:42]
2017-10-25 09:52:48,012 DEBUG identity parts: ['ssh://', 'kamil@', 'example.com'] [interface.py:46]
2017-10-25 09:52:48,012 INFO please confirm user "git" login to "<ssh://kamil@example.com|nist256p1>" using Trezor... [client.py:46]
2017-10-25 09:52:48.014 Python[91064:14997871] -[__NSCFNumber member:]: unrecognized selector sent to instance 0xffff801780b0cdb7
2017-10-25 09:52:48.026 Python[91064:14997871] *** Terminating app due to uncaught exception 'NSInvalidArgumentException', reason: '-[__NSCFNumber member:]: unrecognized selector sent to instance 0xffff801780b0cdb7'
*** First throw call stack:
(
0 CoreFoundation 0x00007fff5475e0fb __exceptionPreprocess + 171
1 libobjc.A.dylib 0x00007fff7b04cc76 objc_exception_throw + 48
2 CoreFoundation 0x00007fff547f6c34 -[NSObject(NSObject) doesNotRecognizeSelector:] + 132
3 CoreFoundation 0x00007fff546d4510 ___forwarding___ + 1456
4 CoreFoundation 0x00007fff546d3ed8 _CF_forwarding_prep_0 + 120
5 CoreFoundation 0x00007fff546a5eb7 __CFRunLoopFindMode + 199
6 CoreFoundation 0x00007fff546a6631 CFRunLoopAddSource + 209
7 IOKit 0x00007fff56e7908c IOHIDDeviceScheduleWithRunLoop + 69
8 IOKit 0x00007fff56e7be25 __IOHIDManagerDeviceApplier + 490
9 IOKit 0x00007fff56e7cdce __IOHIDManagerDeviceAdded + 341
10 IOKit 0x00007fff56e7c29d __IOHIDManagerSetDeviceMatching + 211
11 hid.cpython-36m-darwin.so 0x000000010a61b8d1 hid_enumerate + 209
12 hid.cpython-36m-darwin.so 0x000000010a61ae64 __pyx_pw_3hid_1enumerate + 676
13 Python 0x00000001081a0c72 _PyCFunction_FastCallDict + 463
14 Python 0x00000001082051da call_function + 489
15 Python 0x00000001081fe0a7 _PyEval_EvalFrameDefault + 4811
16 Python 0x00000001082062df _PyFunction_FastCall + 121
17 Python 0x00000001082051b1 call_function + 448
18 Python 0x00000001081fe0a7 _PyEval_EvalFrameDefault + 4811
19 Python 0x000000010820593c _PyEval_EvalCodeWithName + 1719
20 Python 0x000000010820603f fast_function + 218
21 Python 0x00000001082051b1 call_function + 448
22 Python 0x00000001081fe0a7 _PyEval_EvalFrameDefault + 4811
23 Python 0x00000001082062df _PyFunction_FastCall + 121
24 Python 0x0000000108168f71 _PyObject_FastCallDict + 196
25 Python 0x0000000108169094 _PyObject_Call_Prepend + 156
26 Python 0x0000000108168f3c _PyObject_FastCallDict + 143
27 Python 0x0000000108165da2 PyObject_CallFunctionObjArgs + 210
28 Python 0x00000001081fdda0 _PyEval_EvalFrameDefault + 4036
29 Python 0x000000010820593c _PyEval_EvalCodeWithName + 1719
30 Python 0x000000010820603f fast_function + 218
31 Python 0x00000001082051b1 call_function + 448
32 Python 0x00000001081fe140 _PyEval_EvalFrameDefault + 4964
33 Python 0x000000010820593c _PyEval_EvalCodeWithName + 1719
34 Python 0x000000010820603f fast_function + 218
35 Python 0x00000001082051b1 call_function + 448
36 Python 0x00000001081fe140 _PyEval_EvalFrameDefault + 4964
37 Python 0x000000010820593c _PyEval_EvalCodeWithName + 1719
38 Python 0x000000010820603f fast_function + 218
39 Python 0x00000001082051b1 call_function + 448
40 Python 0x00000001081fe140 _PyEval_EvalFrameDefault + 4964
41 Python 0x000000010820593c _PyEval_EvalCodeWithName + 1719
42 Python 0x000000010820603f fast_function + 218
43 Python 0x00000001082051b1 call_function + 448
44 Python 0x00000001081fe140 _PyEval_EvalFrameDefault + 4964
45 Python 0x000000010820593c _PyEval_EvalCodeWithName + 1719
46 Python 0x000000010820620f _PyFunction_FastCallDict + 449
47 Python 0x0000000108168f71 _PyObject_FastCallDict + 196
48 Python 0x00000001082503b7 partial_call + 258
49 Python 0x0000000108168df2 PyObject_Call + 101
50 Python 0x00000001081fe310 _PyEval_EvalFrameDefault + 5428
51 Python 0x00000001082062df _PyFunction_FastCall + 121
52 Python 0x00000001082051b1 call_function + 448
53 Python 0x00000001081fe0a7 _PyEval_EvalFrameDefault + 4811
54 Python 0x00000001082062df _PyFunction_FastCall + 121
55 Python 0x00000001082051b1 call_function + 448
56 Python 0x00000001081fe0a7 _PyEval_EvalFrameDefault + 4811
57 Python 0x00000001082062df _PyFunction_FastCall + 121
58 Python 0x0000000108168f71 _PyObject_FastCallDict + 196
59 Python 0x0000000108169094 _PyObject_Call_Prepend + 156
60 Python 0x0000000108168df2 PyObject_Call + 101
61 Python 0x000000010823a8cb t_bootstrap + 70
62 libsystem_pthread.dylib 0x00007fff7bec56c1 _pthread_body + 340
63 libsystem_pthread.dylib 0x00007fff7bec556d _pthread_body + 0
64 libsystem_pthread.dylib 0x00007fff7bec4c5d thread_start + 13
)
libc++abi.dylib: terminating with uncaught exception of type NSException
sign_and_send_pubkey: signing failed: communication with agent failed
[1] 91064 abort trezor-agent kamil@example.com -vv -s
@romanz sounds this log above indicate some problem on level Python <-> OS X
sounds this log above indicate some problem on level Python <-> OS X
Indeed.
If so, it would be interesting to reproduce this issue on Mac OS using python-trezor
API.
@romanz if You can prepare anything I can run it.
Sounds good - can you please try to reproduce it with https://github.com/romanz/trezor-agent/commit/876c9e659bf221c30891aa54cabe390831b18cab?
It can be run using the following command:
python3 -m libagent.device.repro_segfault
@romanz I tried it. But it isn't that. I've run the script (changed only time from 60*10 to only 30 s) it always works. But in mean time on other shell I did trezor-agent kamil@example.com -s and after second git fetch it crashed. But Your script in meantime still works correctly... So this must have something to do with -s option I believe.
Your script is still going I again started trezor-agent kamil@example.com -s
and two execution of git fetch went fine, third one failed with crash.
Very weird...
So it happens only when the same trezor-agent
process is running for a long (~10 minutes) time, and being interacted via a subshell?
I think time factor doesn't have anything to do with it, sorry for misleading in first place. I can reproduce that right now in 45-60s. I was thinking it's time factor, but probably because I was doing git
between longer period of time. But now if I do git fetch
one by one without pause eventually after second or third time it crashes.
BTW, did any of the Mac OS users of trezor-agent
had encountered this issue?
@baremetalfreak
@mnemnion
@fruitloop
@oohaysmlm
@robbert36
(asking because I don't have access to a Mac OS machine...)
@galuszkak Let's try to reproduce this with 2 separate processes.
In the first shell, run the trezor-agent
process:
$ trezor-agent -vv -e ed25519 git@github.com -- cat
2017-11-02 17:51:01,778 DEBUG parsed identity: {'host': 'github.com', 'path': None, 'proto': None, 'port': None, 'user': 'git'} [interface.py:30]
2017-11-02 17:51:01,778 DEBUG identity parts: ['ssh://', 'git@', 'github.com'] [interface.py:46]
2017-11-02 17:51:01,779 INFO identity #0: <ssh://git@github.com|ed25519> [__init__.py:208]
2017-11-02 17:51:01,781 DEBUG local SSH version: b'OpenSSH_7.2p2 Ubuntu-4ubuntu2.2, OpenSSL 1.0.2g 1 Mar 2016\n' [__init__.py:99]
2017-11-02 17:51:01,782 DEBUG serving on /tmp/trezor-ssh-agent-7s2ycdy2 [server.py:30]
2017-11-02 17:51:01,782 DEBUG server thread started [server.py:84]
2017-11-02 17:51:01,782 INFO running ['cat'] with {'SSH_AUTH_SOCK': '/tmp/trezor-ssh-agent-7s2ycdy2', 'SSH_AGENT_PID': '28888'} [server.py:119]
2017-11-02 17:51:01,782 DEBUG waiting for connection on /tmp/trezor-ssh-agent-7s2ycdy2 [server.py:92]
2017-11-02 17:51:01,784 DEBUG subprocess 28893 is running [server.py:126]
In the second shell, run the following commands (using the UNIX socket path above):
$ export SSH_AUTH_SOCK=/tmp/trezor-ssh-agent-7s2ycdy2
$ git push
Everything up-to-date
$ git push
Everything up-to-date
Does this setup reproduce the segfault?
@romanz I have never seen it, but I do not currently use trezor for git. Let me set it up and see if it shows up.
@romanz I don't use the trezor for ssh at the moment
@romanz OK, I think we narrow one thing. This failed after second git fetch
. Also I didn't use flag -e I just take default key algorithm.
$ trezor-agent -vv kamil@flyrlabs.com -- cat
2017-11-05 09:18:55,991 DEBUG parsed identity: {'proto': None, 'user': 'kamil', 'host': 'flyrlabs.com', 'port': None, 'path': None} [interface.py:30]
2017-11-05 09:18:55,991 DEBUG identity parts: ['ssh://', 'kamil@', 'flyrlabs.com'] [interface.py:46]
2017-11-05 09:18:55,991 INFO identity #0: <ssh://kamil@flyrlabs.com|nist256p1> [__init__.py:208]
2017-11-05 09:18:56,014 DEBUG local SSH version: b'OpenSSH_7.5p1, LibreSSL 2.5.4\n' [__init__.py:99]
2017-11-05 09:18:56,023 DEBUG serving on /var/folders/h6/94cjw0j97g59d_w5wmwhcyl80000gn/T/trezor-ssh-agent-1ieyjvtu [server.py:30]
2017-11-05 09:18:56,023 DEBUG server thread started [server.py:84]
2017-11-05 09:18:56,023 DEBUG waiting for connection on /var/folders/h6/94cjw0j97g59d_w5wmwhcyl80000gn/T/trezor-ssh-agent-1ieyjvtu [server.py:92]
2017-11-05 09:18:56,023 INFO running ['cat'] with {'SSH_AUTH_SOCK': '/var/folders/h6/94cjw0j97g59d_w5wmwhcyl80000gn/T/trezor-ssh-agent-1ieyjvtu', 'SSH_AGENT_PID': '65203'} [server.py:119]
2017-11-05 09:18:56,026 DEBUG subprocess 65230 is running [server.py:126]
2017-11-05 09:19:23,157 DEBUG welcome agent
[...][...]
2017-11-05 09:19:36,313 DEBUG key type: b'ecdsa-sha2-nistp256' [formats.py:55]
2017-11-05 09:19:36,313 DEBUG curve name: b'nistp256' [formats.py:62]
2017-11-05 09:19:36,313 DEBUG looking for ab:0c:37:53:aa:b4:26:a7:c0:5b:6c:37:1b:a2:fa:32 [protocol.py:128]
2017-11-05 09:19:36,313 DEBUG loading SSH public key: 'ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBPV2v9GXM1FK+JZRwPqB3rKFA/bl9p4qX/x/E/A2Ya2kuwaFpPM/hOSXn+gMT8L/c9ZL2M5z9QXT0mbuRGA7xKg= <ssh://kamil@flyrlabs.com|nist256p1>\n' [formats.py:192]
2017-11-05 09:19:36,313 DEBUG key type: b'ecdsa-sha2-nistp256' [formats.py:55]
2017-11-05 09:19:36,314 DEBUG curve name: b'nistp256' [formats.py:62]
2017-11-05 09:19:36,314 DEBUG loaded ecdsa-sha2-nistp256 public key: ab:0c:37:53:aa:b4:26:a7:c0:5b:6c:37:1b:a2:fa:32 [formats.py:198]
2017-11-05 09:19:36,314 DEBUG using key b'<ssh://kamil@flyrlabs.com|nist256p1>' (ab:0c:37:53:aa:b4:26:a7:c0:5b:6c:37:1b:a2:fa:32) [protocol.py:135]
2017-11-05 09:19:36,314 DEBUG signing 207-byte blob with "<ssh://kamil@flyrlabs.com|nist256p1>" key [protocol.py:142]
2017-11-05 09:19:36,314 DEBUG key type: b'ecdsa-sha2-nistp256' [formats.py:55]
2017-11-05 09:19:36,314 DEBUG curve name: b'nistp256' [formats.py:62]
2017-11-05 09:19:36,315 DEBUG b'ssh-connection': user b'git' via b'publickey' (b'ecdsa-sha2-nistp256') [client.py:38]
2017-11-05 09:19:36,315 DEBUG nonce: b'\xaf>\x0e\\`#?|\nM\xf6YK\xe7-6\xb3O\x05\x81\x81\xaa5\x18(\x7f0\x1a\xec\xc0\xd2\xe2' [client.py:39]
2017-11-05 09:19:36,315 DEBUG fingerprint: ab:0c:37:53:aa:b4:26:a7:c0:5b:6c:37:1b:a2:fa:32 [client.py:41]
2017-11-05 09:19:36,315 DEBUG hidden challenge size: 207 bytes [client.py:42]
2017-11-05 09:19:36,315 DEBUG identity parts: ['ssh://', 'kamil@', 'flyrlabs.com'] [interface.py:46]
2017-11-05 09:19:36,315 INFO please confirm user "git" login to "<ssh://kamil@flyrlabs.com|nist256p1>" using Trezor... [client.py:46]
[1] 65203 segmentation fault trezor-agent -vv kamil@flyrlabs.com -- cat
It's really weird. I'll try to find a Mac OS machine to try and reproduce this issue... BTW, did this issue happen on a specific machine / OS version?
I tried on both latest MacBook Pro 2017 with High Sierra OS X (10.13.1).
@romanz if You want we can schedule session when I can give remote access so You can test it by Yourself without looking for mac.
Sounds good, but before that - could you record the failing terminal session (e.g. using asciinema)? Please use the most verbose logging (if possible)...
Will do it today/tommorow.
I'm having this issue too. I hope we can resolve it, I also have a MBP with Touch Bar and High Sierra (but it happened on Sierra too).
@L-Cafe Thanks for letting me know! Could you record the failing terminal session (e.g. using https://asciinema.org/)? Please use the most verbose logging (if possible)...
Not sure what you wanted me to record, I recorded the output of both trezor-agent
and trezor-gpg
, which seem to be failing for the same reason.
The failure above can be fixed by downgrading trezor
package to 0.7.16
version:
$ pip install trezor==0.7.16
The latest version of trezor
has a few incompatible changes - will be solved by #180.
Still getting errors.
https://asciinema.org/a/4g0xklsOqXrsiRRThE6vh1eSP (GPG)
And a funny bug: When recording a terminal session through asciinema rec
, SSH login works as expected. When it's not recording, I get the following:
└─[$] <> trezor-agent -c x000@localhost
[1] 1745 segmentation fault trezor-agent -c x000@localhost
Additionally: The above only fails when the port is open and the pubkey is added to authorized_keys. That is, if I close the port, it fails as expected because the port is closed. And if I don't add the pubkey or disable SSH login through Settings, it will fall back to a password prompt.
Regarding the GPG-related failure: could you please attach the log of trezor-gpg-agent
?
(it should be stored at ~/.gnupg/trezor/gpg-agent.log
)
Regarding the segfault - is it possible to get the stack of the failing process (e.g. via a coredump)? Is it similar to https://github.com/romanz/trezor-agent/issues/157#issuecomment-339222489?
@romanz can You give list of steps You want to record? I can still do it. Forgot about this issue.
No problem :) Could you please record an SSH session causing a segfault (e.g. https://github.com/romanz/trezor-agent/issues/157#issuecomment-339222489 or https://github.com/romanz/trezor-agent/issues/157#issuecomment-341950059)?
It seems this has been resolved on my machine after downloading the newest version from pip.
Additionally, conflict exists with Krypton https://krypt.co which may cause confusing output to be printed to the screen. Furthermore, if enabled, paired, and successfully authorised (via the smartphone app), it will bypass trezor-agent's functionality completely. That is: it doesn't matter whether the TREZOR provides a valid answer, or whether the TREZOR-generated public key is actually installed on the remote server, because you can simply use Krypton to allow the request.
Thanks for letting me know about Krypton :) Will try it out later this week.
Krypton indeed seems as great project! If you'll use the following command, you can override it with TREZOR-based authentication:
$ trezor-agent user@host --shell
$ ssh-add -L
$ ssh user@host
From time to time, after maybe 5-10 min of not using trezor (in that time it's working fine) until I have this issue/error: