Unhandled error when sender sends message in wrong order? (may be I'm not sure)

[copyninja]

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]

Can you please give a JSON trace of the communication happening between both sides until the crash?