Unhandled error when sender sends message in wrong order? (may be I'm not sure)
copyninja opened this issue · 1 comments
copyninja commented
Hi,
I was experimenting with magic-wormhole protocol using golang and was experimenting send functionality. Then I encountered error on my side and noticed on mailbox server side there is this stack trace dumped on screen.
2018-08-24T09:40:52+0530 [_GenericHTTPChannelProtocol,2,127.0.0.1] ws client connecting: tcp4:127.0.0.1:57960
2018-08-24T09:40:53+0530 [_GenericHTTPChannelProtocol,2,127.0.0.1] creating nameplate#6 for app_id lothar.com/wormhole/text-or-file-xfer
2018-08-24T09:40:53+0530 [_GenericHTTPChannelProtocol,2,127.0.0.1] spawning #5mcm5y333z6ze for app_id lothar.com/wormhole/text-or-file-xfer
2018-08-24T09:41:11+0530 [_GenericHTTPChannelProtocol,2,127.0.0.1] Unhandled Error
Traceback (most recent call last):
File "c:\users\invakam2\appdata\local\programs\python\python36\lib\site-packages\twisted\python\log.py", line 103, in callWithLogger
return callWithContext({"system": lp}, func, *args, **kw)
File "c:\users\invakam2\appdata\local\programs\python\python36\lib\site-packages\twisted\python\log.py", line 86, in callWithContext
return context.call({ILogContext: newCtx}, func, *args, **kw)
File "c:\users\invakam2\appdata\local\programs\python\python36\lib\site-packages\twisted\python\context.py", line 122, in callWithContext
return self.currentContext().callWithContext(ctx, func, *args, **kw)
File "c:\users\invakam2\appdata\local\programs\python\python36\lib\site-packages\twisted\python\context.py", line 85, in callWithContext
return func(*args,**kw)
--- <exception caught here> ---
File "c:\users\invakam2\appdata\local\programs\python\python36\lib\site-packages\twisted\internet\selectreactor.py", line 149, in _doReadOrWrite
why = getattr(selectable, method)()
File "c:\users\invakam2\appdata\local\programs\python\python36\lib\site-packages\twisted\internet\tcp.py", line 205, in doRead
return self._dataReceived(data)
File "c:\users\invakam2\appdata\local\programs\python\python36\lib\site-packages\twisted\internet\tcp.py", line 211, in _dataReceived
rval = self.protocol.dataReceived(data)
File "c:\users\invakam2\appdata\local\programs\python\python36\lib\site-packages\autobahn\twisted\websocket.py", line 131, in dataReceived
self._dataReceived(data)
File "c:\users\invakam2\appdata\local\programs\python\python36\lib\site-packages\autobahn\websocket\protocol.py", line 1175, in _dataReceived
self.consumeData()
File "c:\users\invakam2\appdata\local\programs\python\python36\lib\site-packages\autobahn\websocket\protocol.py", line 1187, in consumeData
while self.processData() and self.state != WebSocketProtocol.STATE_CLOSED:
File "c:\users\invakam2\appdata\local\programs\python\python36\lib\site-packages\autobahn\websocket\protocol.py", line 1553, in processData
fr = self.onFrameEnd()
File "c:\users\invakam2\appdata\local\programs\python\python36\lib\site-packages\autobahn\websocket\protocol.py", line 1674, in onFrameEnd
self._onMessageEnd()
File "c:\users\invakam2\appdata\local\programs\python\python36\lib\site-packages\autobahn\twisted\websocket.py", line 159, in _onMessageEnd
self.onMessageEnd()
File "c:\users\invakam2\appdata\local\programs\python\python36\lib\site-packages\autobahn\websocket\protocol.py", line 627, in onMessageEnd
self._onMessage(payload, self.message_is_binary)
File "c:\users\invakam2\appdata\local\programs\python\python36\lib\site-packages\autobahn\twisted\websocket.py", line 162, in _onMessage
self.onMessage(payload, isBinary)
File "c:\users\invakam2\documents\playarea\python\magic-wormhole-mailbox-server\src\wormhole_mailbox_server\server_websocket.py", line 125, in onMessage
msg = bytes_to_dict(payload)
File "c:\users\invakam2\documents\playarea\python\magic-wormhole-mailbox-server\src\wormhole_mailbox_server\util.py", line 25, in bytes_to_dict
assert isinstance(d, dict)
builtins.AssertionError:Here is the go code which causes this.
package main
import (
"encoding/hex"
"encoding/json"
"fmt"
"github.com/gorilla/websocket"
"log"
"net/url"
"salsa.debian.org/vasudev/magicwormhole/internal/core"
peer "salsa.debian.org/vasudev/magicwormhole/internal/peermessages"
server "salsa.debian.org/vasudev/magicwormhole/internal/servermessages"
"time"
)
func startSend(incoming chan server.IncommingMessage, c *websocket.Conn) {
k := core.NewKey("lothar,com/wormhole/text-or-file-xfer", "side0", make(map[string]string))
var sharedKey []byte
var nameplate, mailbox, code, phase, text string
nameplateRelease := false
for {
select {
case msg := <-incoming:
switch msg.(type) {
case *server.Welcome:
w := msg.(*server.Welcome)
if motd, ok := w.Welcome["motd"]; ok {
fmt.Printf("Message from server: %s\n", motd)
}
if err := c.WriteJSON(server.Bind{"lothar.com/wormhole/text-or-file-xfer", "side0"}); err != nil {
log.Fatal("Failed to bind with server, ", err)
}
if err := c.WriteJSON(server.Allocate{}); err != nil {
log.Fatal("Failed to request allocate nameplate: ", err)
}
case *server.Allocated:
a := msg.(*server.Allocated)
nameplate = *a.Nameplate
if err := c.WriteJSON(server.Claim{nameplate}); err != nil {
log.Fatal("Failed to claim the nameplate: ", err)
}
fmt.Printf("Please enter a code (without nameplate): ")
var x string
fmt.Scanf("%s", &x)
code = fmt.Sprintf("%s-%s", nameplate, x)
fmt.Printf("Please run `wormhole rx %s` on other end\n", code)
case *server.Claimed:
claimed := msg.(*server.Claimed)
mailbox = *claimed.Mailbox
if err := c.WriteJSON(server.Open{mailbox}); err != nil {
log.Fatal("Failed to open mailbox: ", err)
}
fmt.Print("Please enter message: ")
fmt.Scanf("%s", &text)
pake, err := k.BuildPake(code)
if err != nil {
log.Fatal("Failed to build pake: ", err)
}
time.Sleep(time.Duration(10 * time.Second))
if err = c.WriteJSON(server.Add{"pake", hex.EncodeToString(pake)}); err != nil {
log.Fatal("Failed to send pake message: ", err)
}
myVersion, err := k.PrepareVersionMessage(sharedKey)
if err != nil {
log.Fatal("Failed to create version image: ", err)
}
if err = c.WriteJSON(myVersion); err != nil {
log.Fatal("Failed to send my version: ", err)
}
case *server.Message:
m := msg.(*server.Message)
if *m.Side != "side0" {
if !nameplateRelease {
if err := c.WriteJSON(server.Release{nameplate}); err != nil {
log.Fatal("Failed to release nameplate: ", err)
}
}
switch *m.Phase {
case "pake":
var err error
sharedKey, err = k.ComputeKey(*m.Body)
if err != nil {
log.Fatal("Failed to compute key: ", err)
}
fmt.Printf("shared key: %x\n", sharedKey)
default:
fmt.Printf("phase: %s side: %s\n", *m.Phase, *m.Side)
phaseKey := core.DerivePhaseKey(sharedKey, *m.Side, *m.Phase)
body, err := hex.DecodeString(*m.Body)
if err != nil {
log.Fatal("failed to decode body bytes: ", err)
}
data, err := core.DecryptData(phaseKey, body)
if err != nil {
log.Fatal("failed to decrypt payload: ", err)
}
switch *m.Phase {
case "version":
var version peer.Version
if err := json.Unmarshal(data, &version); err != nil {
log.Fatal("payload unmarshaling for version failed: ", err)
}
if len(version.AppVersion) != 0 {
fmt.Printf("%s\n", version.AppVersion)
}
fmt.Printf("key verified. Sending data... \n")
phase = "0"
phaseKey := core.DerivePhaseKey(sharedKey, *m.Side, phase)
encrypted, err := core.EncryptData(phaseKey, []byte(text))
if err != nil {
log.Fatal("Failed to encrypt data: ", err)
}
if err = c.WriteJSON(server.Add{phase, hex.EncodeToString(encrypted)}); err != nil {
log.Fatal("Failed to send message to other side: ", err)
}
default:
var answer peer.Answer
if err := json.Unmarshal(data, &answer); err != nil {
log.Fatalf("Failed to unmarshal the answer: %s, unrecognized message: %s", err, string(data))
}
switch answer.Answer.(type) {
case peer.MessageAck:
m := answer.Answer.(peer.MessageAck)
if m.Ack == "ok" {
fmt.Println("text message sent succesfully")
close := server.Close{mailbox, "happy"}
if err := c.WriteJSON(close); err != nil {
log.Fatal("Failed to close mailbox: ", err)
}
return
}
}
}
}
}
case *server.Released:
nameplateRelease = true
}
}
}
}
func main() {
u := url.URL{Scheme: "ws", Host: "localhost:4000", Path: "v1"}
log.Printf("connecting to %s", u.String())
c, _, err := websocket.DefaultDialer.Dial(u.String(), nil)
if err != nil {
log.Fatal("dial: ", err)
}
defer c.Close()
input := make(chan server.IncommingMessage)
inputDone := make(chan bool)
inputTimer := time.NewTicker(time.Second)
defer inputTimer.Stop()
go func() {
defer close(input)
var in server.IncommingMessage
for {
select {
case <-inputDone:
return
case <-inputTimer.C:
_, message, err := c.ReadMessage()
if err != nil {
log.Println("Read: ", err)
}
in, err = server.Decode(json.RawMessage(message))
if err != nil {
log.Fatal("Decode: ", err, string(message))
}
input <- in
}
}
}()
startSend(input, c)
}You would need to use salsa.debian.org/vasudev/magicwormhole for building this binary. Once built just execute and enter the code without nameplate (nameplate got from server). And you will see abrupt connection closure error and above trace back on mailbox server.
I was expecting an error message instead suggesting what might have gone wrong. Ofcourse its my code at fault but the above error is not handled in server side.
piegamesde commented
Can you please give a JSON trace of the communication happening between both sides until the crash?