search

magic-wormhole / magic-wormhole.rs

Rust implementation of Magic Wormhole, with new features and enhancements
European Union Public License 1.2
722 stars 78 forks source link

Panic triggered when sending file to Wormhole William #136

Closed Alch-Emi closed 2 years ago

Alch-Emi commented 2 years ago

When sending any file to the Wormhole William app (android), magic-wormhole.rs panics before the transfer is complete.

Running magic-wormhole installed from source on commit 166d434 (latest), and Wormhole William version 1.0.4 (latest fdroid). Running wormhole send <filename> on sending device, and entering the code in WW initially produces an accept/deny prompt, as expected. However, selecting "accept" causes wormhole.rs to panic with the error appended to the bottom of this post.

This error does not occur with standard python wormhole, nor with the reverse configuration (ww -> wrs). The error on WW's side is simply "Receive file error: failed to establish connection".

I'm running magic-wormhole.rs on Fedora 35 (although I had this problem on 34 as well), built locally with cargo 1.56.0 (4ed5d137b 2021-10-04)

Please let me know if there is any other information I can help provide, or if I should move this over to WW's issue tracker instead. I figured I ought to post it here, since panics are rarely expected behavior, even with a misbehaving remote, but I'm happy to move it if it's their client acting up.

Thanks so much for your help and for the awesome app!

[2021-11-21T06:39:19Z DEBUG wormhole] Logging enabled.
[2021-11-21T06:39:19Z DEBUG tungstenite::handshake::client] Client handshake done.
[2021-11-21T06:39:19Z DEBUG magic_wormhole::core::rendezvous] Received Welcome(WelcomeMessage { .. })
[2021-11-21T06:39:19Z DEBUG magic_wormhole::core::rendezvous] Sending Bind { appid: lothar.com/wormhole/text-or-file-xfer, side: MySide(79db9246c0) }
[2021-11-21T06:39:19Z DEBUG magic_wormhole::core::rendezvous] Received Ack
[2021-11-21T06:39:19Z INFO  magic_wormhole::core::rendezvous] Connected to server
[2021-11-21T06:39:19Z DEBUG magic_wormhole::core::rendezvous] Sending Allocate
[2021-11-21T06:39:19Z DEBUG magic_wormhole::core::rendezvous] Received Ack
[2021-11-21T06:39:19Z DEBUG magic_wormhole::core::rendezvous] Received Allocated(4)
[2021-11-21T06:39:19Z DEBUG magic_wormhole::core::rendezvous] Sending Claim(4)
[2021-11-21T06:39:19Z DEBUG magic_wormhole::core::rendezvous] Received Ack
[2021-11-21T06:39:19Z DEBUG magic_wormhole::core::rendezvous] Received Claimed(53ibosonhxwes)
[2021-11-21T06:39:19Z DEBUG magic_wormhole::core::rendezvous] Sending Open(53ibosonhxwes)
[2021-11-21T06:39:19Z DEBUG magic_wormhole::core::rendezvous] Received Ack
[2021-11-21T06:39:19Z DEBUG magic_wormhole::core] Connected to mailbox 53ibosonhxwes
This wormhole's code is: 4-atmosphere-edict
On the other computer, please run:

wormhole receive 4-atmosphere-edict

[2021-11-21T06:39:19Z DEBUG magic_wormhole::core::rendezvous] Sending Add { phase: pake, body: <JSON dict with key 'pake_v1'> }
[2021-11-21T06:39:19Z DEBUG magic_wormhole::core::rendezvous] Received Ack
[2021-11-21T06:39:19Z DEBUG magic_wormhole::core::rendezvous] Received EncryptedMessage { side: TheirSide(79db9246c0), phase: pake, body: <JSON dict with key 'pake_v1'>
[2021-11-21T06:39:45Z DEBUG magic_wormhole::core::rendezvous] Received EncryptedMessage { side: TheirSide(7a43000d89), phase: pake, body: <JSON dict with key 'pake_v1'>
[2021-11-21T06:39:45Z DEBUG magic_wormhole::core::rendezvous] Sending Add { phase: version, body: <74 bytes> }
[2021-11-21T06:39:45Z DEBUG magic_wormhole::core::rendezvous] Received Ack
[2021-11-21T06:39:45Z DEBUG magic_wormhole::core::rendezvous] Received EncryptedMessage { side: TheirSide(79db9246c0), phase: version, body: <74 bytes>
[2021-11-21T06:39:45Z DEBUG magic_wormhole::core::rendezvous] Received EncryptedMessage { side: TheirSide(7a43000d89), phase: version, body: <59 bytes>
[2021-11-21T06:39:45Z DEBUG magic_wormhole::core::rendezvous] Sending Release(4)
[2021-11-21T06:39:45Z DEBUG magic_wormhole::core::rendezvous] Received Ack
[2021-11-21T06:39:45Z DEBUG magic_wormhole::core::rendezvous] Received Released
[2021-11-21T06:39:45Z INFO  magic_wormhole::core] Connected to peer (PAKE successful)
Successfully connected to peer.
Decoded message: Message { class: SuccessResponse, method: Method(1), transaction_id: TransactionId(0xE721CEDB0DEDB64B511B98D0), attributes: [Known { inner: XorMappedAddress(XorMappedAddress(REDACTED)), padding: Some(Padding([])) }, Known { inner: MappedAddress(MappedAddress(REDACTED)), padding: Some(Padding([])) }, Unknown { inner: RawAttribute { attr_type: AttributeType(32811), value: [0, 1, 13, 150, 188, 34, 185, 244] }, padding: Some(Padding([])) }, Unknown { inner: RawAttribute { attr_type: AttributeType(32812), value: [0, 1, 13, 151, 188, 34, 185, 244] }, padding: Some(Padding([])) }, Known { inner: Software(Software { description: "Coturn-4.5.2 'dan Eider'" }), padding: Some(Padding([])) }] }
[2021-11-21T06:39:45Z DEBUG magic_wormhole::transit] Our external IP address is REDACTED
[2021-11-21T06:39:45Z DEBUG magic_wormhole::transfer] Sending transit message 'Hints { direct_tcp: {DirectHint { hostname: "REDACTED", port: 33595 }, DirectHint { hostname: "172.17.0.1", port: 36637 }, DirectHint { hostname: "192.168.122.1", port: 33595 }, DirectHint { hostname: "192.168.122.1", port: 36637 }, DirectHint { hostname: "fc00:bbbb:bbbb:bb01::9:c600", port: 36637 }, DirectHint { hostname: "172.23.0.1", port: 36637 }, DirectHint { hostname: "fc00:bbbb:bbbb:bb01::9:c600", port: 33595 }, DirectHint { hostname: "172.18.0.1", port: 33595 }, DirectHint { hostname: "REDACTED", port: 36637 }, DirectHint { hostname: "172.24.0.1", port: 36637 }, DirectHint { hostname: "REDACTED", port: 33595 }, DirectHint { hostname: "10.72.198.1", port: 36637 }, DirectHint { hostname: "172.20.0.1", port: 33595 }, DirectHint { hostname: "172.21.0.1", port: 33595 }, DirectHint { hostname: "REDACTED", port: 36637 }, DirectHint { hostname: "172.19.0.1", port: 36637 }, DirectHint { hostname: "172.22.0.1", port: 33595 }, DirectHint { hostname: "172.20.0.1", port: 36637 }, DirectHint { hostname: "172.24.0.1", port: 33595 }, DirectHint { hostname: "172.19.0.1", port: 33595 }, DirectHint { hostname: "REDACTED", port: 36637 }, DirectHint { hostname: "2620:8d:8000:1058:5972:1086:1aa4:50d7", port: 33595 }, DirectHint { hostname: "172.23.0.1", port: 33595 }, DirectHint { hostname: "172.17.0.1", port: 33595 }, DirectHint { hostname: "172.21.0.1", port: 36637 }, DirectHint { hostname: "172.18.0.1", port: 36637 }, DirectHint { hostname: "172.22.0.1", port: 36637 }}, relay: {DirectHint { hostname: "transit.magic-wormhole.io", port: 4001 }} }
[2021-11-21T06:39:45Z DEBUG magic_wormhole::core::rendezvous] Sending Add { phase: 0, body: <2015 bytes> }
[2021-11-21T06:39:45Z DEBUG magic_wormhole::core::rendezvous] Received Ack
[2021-11-21T06:39:45Z DEBUG magic_wormhole::transfer] Sending file offer
[2021-11-21T06:39:45Z DEBUG magic_wormhole::core::rendezvous] Sending Add { phase: 1, body: <101 bytes> }
[2021-11-21T06:39:45Z DEBUG magic_wormhole::core::rendezvous] Received EncryptedMessage { side: TheirSide(79db9246c0), phase: 0, body: <2015 bytes>
[2021-11-21T06:39:45Z DEBUG magic_wormhole::core::rendezvous] Received Ack
[2021-11-21T06:39:45Z DEBUG magic_wormhole::core::rendezvous] Received EncryptedMessage { side: TheirSide(79db9246c0), phase: 1, body: <101 bytes>
[2021-11-21T06:39:45Z DEBUG magic_wormhole::core::rendezvous] Received EncryptedMessage { side: TheirSide(7a43000d89), phase: 0, body: <129 bytes>
[2021-11-21T06:39:45Z DEBUG magic_wormhole::transfer] received transit message: TransitType { abilities_v1: [DirectTcpV1, RelayV1], hints_v1: [] }
[2021-11-21T06:39:48Z DEBUG magic_wormhole::core::rendezvous] Received EncryptedMessage { side: TheirSide(7a43000d89), phase: 1, body: <85 bytes>
Error: 
   0: Corrupt message received
   1: expected value at line 1 column 27

Location:
   /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/core/src/result.rs:1915

  ━━━━━ BACKTRACE ━━━━━
                                ⋮ 2 frames hidden ⋮                               
   3: wormhole::main::main::{{closure}}::h9121550176b57768
      at <unknown source file>:<unknown line>
   4: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h5f387e8fbe28d045
      at <unknown source file>:<unknown line>
   5: std::thread::local::LocalKey<T>::with::hc15afc704873b524
      at <unknown source file>:<unknown line>
   6: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h89f3aeb70f9e2bf8
      at <unknown source file>:<unknown line>
   7: async_io::driver::block_on::h7a022a2b2d808d18
      at <unknown source file>:<unknown line>
   8: std::thread::local::LocalKey<T>::with::h6b86ee74d8cf517b
      at <unknown source file>:<unknown line>
   9: std::thread::local::LocalKey<T>::with::hffb8b80ae70ec532
      at <unknown source file>:<unknown line>
  10: async_std::task::builder::Builder::blocking::h098be1146fe1805f
      at <unknown source file>:<unknown line>
  11: wormhole::main::h1421189923cc326a
      at <unknown source file>:<unknown line>
  12: std::sys_common::backtrace::__rust_begin_short_backtrace::h71285ddb4bbe8d1e
      at <unknown source file>:<unknown line>
  13: std::rt::lang_start::{{closure}}::hebb6c8292cee4dd8
      at <unknown source file>:<unknown line>
  14: core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once::h97e9d5f21cbee92f
      at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/core/src/ops/function.rs:259
  15: std::panicking::try::do_call::hdfecd950eba8f698
      at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/std/src/panicking.rs:403
  16: std::panicking::try::h3c77c8ba3eb0735c
      at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/std/src/panicking.rs:367
  17: std::panic::catch_unwind::h8e0d62076d8d837e
      at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/std/src/panic.rs:129
  18: std::rt::lang_start_internal::{{closure}}::h647045b4c6a22e67
      at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/std/src/rt.rs:45
  19: std::panicking::try::do_call::h905d96e4a757647e
      at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/std/src/panicking.rs:403
  20: std::panicking::try::hc113426beb3c908b
      at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/std/src/panicking.rs:367
  21: std::panic::catch_unwind::h74f684ea7038ea12
      at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/std/src/panic.rs:129
  22: std::rt::lang_start_internal::h5ba185919d396c97
      at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/std/src/rt.rs:45
  23: main<unknown>
      at <unknown source file>:<unknown line>
  24: __libc_start_call_main<unknown>
      at <unknown source file>:<unknown line>
  25: __libc_start_main@@GLIBC_2.34<unknown>
      at <unknown source file>:<unknown line>
  26: _start<unknown>
      at <unknown source file>:<unknown line>

(output from running wormhole --log send <filename> with RUST_BACKTRACE=1)

piegamesde commented 2 years ago

And of course, my overly verbose logging still doesn't include the relevant information :( I was in the process of improving things on the logging side anyways, so I'll finish them first before I start investigating this issue.

Generally, it looks like the Go side is sending a message that the Rust side is not happy with. Without knowing the specific message that caused the error, either side may be at fault so it was the right thing to post the bug report here. Especially as the Rust code currently may be overly strict in some cases.

piegamesde commented 2 years ago

I finally came back to this, and to me this is a bug in the Go implementation. The message they send is:

{"answer":{"message_ack":"","file_ack":"ok"}}

This is an enum, and as such the fields message_ack and file_ack are mutually exclusive. I suppose that Go does not distinguish between "empty string" and "no string", where as Rust does. I also assume that this problem will appear on every enum message type (with that encoding), and that it is not specific to this one.

Alch-Emi commented 2 years ago

Thank you so much for investigating! Should I pass this off to the developers of Wormhole William then?

piegamesde commented 2 years ago

Yes, please. You can link this issue there for further context.

psanford commented 2 years ago

I will update wormhole-william to not send the additional fields in this message.

However, I'm not sure this strict protocol handling in the rust code is ideal. If the rust implementation panics on any unexpected fields in messages that will make it very difficult to add backwards compatible extensions to the protocol in the future. Just something to consider.

I've opened https://github.com/psanford/wormhole-william/issues/59 to track the Go change.

piegamesde commented 2 years ago

I'm not sure this strict protocol handling in the rust code is ideal. If the rust implementation panics on any unexpected fields in messages that will make it very difficult to add backwards compatible extensions to the protocol in the future.

Yes, you are totally right on that. This is tracked in #27. For future proofing, this means that we shall accept additional fields in structs (automatically done by serde) and unknown enum variants (partially implemented).

This message is different in the fact that it kind of represents an enum with two variants, and I'd say it is fine to consider this as illegal. But how should we deal with messages like: {"answer":{"message_ack": null,"file_ack":"ok"}} (i.e. only one non-null field)? I'd say it is reasonable to accept this as valid (as long as the field of the variant itself may never be null), but I'm not sure if our code currently accepts that.

psanford commented 2 years ago

The latest version of Wormhole William on the Google Play store now has this fix.