From 9f1985373e6d2764d7def3dbb25064e2ecd4fc3e Mon Sep 17 00:00:00 2001 From: AJ ONeal Date: Wed, 15 Jul 2020 03:33:23 -0600 Subject: [PATCH] yet more logs --- mplexer/conn.go | 3 +++ mplexer/connwrap.go | 19 ++++++++++---- mplexer/decoder.go | 3 ++- mplexer/dns01/dns01.go | 4 +-- mplexer/encoder.go | 2 +- mplexer/listener.go | 4 +-- mplexer/routemux.go | 52 +++++++++++++++++++++++++++++++++----- mplexer/telebit.go | 8 +++--- mplexer/websockettunnel.go | 17 +++++++++---- 9 files changed, 86 insertions(+), 26 deletions(-) diff --git a/mplexer/conn.go b/mplexer/conn.go index dd490e0..5e6657d 100644 --- a/mplexer/conn.go +++ b/mplexer/conn.go @@ -2,6 +2,7 @@ package telebit import ( "bufio" + "fmt" "net" "time" ) @@ -83,11 +84,13 @@ func (c *Conn) LocalAddr() net.Addr { // LocalAddr returns the local network address. func (c *Conn) LocalAddr() net.Addr { + fmt.Println("[warn] LocalAddr() address source/target switch?") return &c.relaySourceAddr } // RemoteAddr returns the remote network address. func (c *Conn) RemoteAddr() net.Addr { + fmt.Println("[warn] RemoteAddr() address source/target switch?") return &c.relayTargetAddr } diff --git a/mplexer/connwrap.go b/mplexer/connwrap.go index d3433ff..e338165 100644 --- a/mplexer/connwrap.go +++ b/mplexer/connwrap.go @@ -88,11 +88,15 @@ func (c *ConnWrap) Scheme() string { return "" } -/* +// CheckServername returns the servername without detection +func (c *ConnWrap) CheckServername() string { + return c.servername +} + +// SetServername sets the servername without detection func (c *ConnWrap) SetServername(name string) { c.servername = name } -*/ // Servername may return Servername or Hostname as hinted by a tunnel or buffered peeking func (c *ConnWrap) Servername() string { @@ -127,13 +131,18 @@ func (c *ConnWrap) isEncrypted() bool { return *c.encrypted } + var encrypted bool + // TODO: how to allow / detect / handle protocols where the server hello happens first? c.SetDeadline(time.Now().Add(5 * time.Second)) n := 6 - b, _ := c.Peek(n) - fmt.Println("[debug] Peek(n)", b, string(b)) + b, err := c.Peek(n) + fmt.Printf("[debug] [wrap] Peek(%d): %s %s %s\n", n, b, string(b), err) + if nil != err { + // TODO return error on error? + return encrypted + } defer c.SetDeadline(time.Time{}) - var encrypted bool if len(b) >= n { // SSL v3.x / TLS v1.x // 0: TLS Byte diff --git a/mplexer/decoder.go b/mplexer/decoder.go index 333dc5b..b8a1b21 100644 --- a/mplexer/decoder.go +++ b/mplexer/decoder.go @@ -4,6 +4,7 @@ import ( "encoding/hex" "fmt" "io" + "log" ) // Decoder handles a Reader stream containing mplexy-encoded clients @@ -32,7 +33,7 @@ func (d *Decoder) Decode(out Router) error { for { b := make([]byte, d.bufferSize) n, err := d.in.Read(b) - fmt.Println("[debug] [decoder] [srv] Tunnel read", n) + log.Println("[debug] [decoder] [srv] Tunnel read", n, string(b[:n])) if n > 0 { rx <- b[:n] } diff --git a/mplexer/dns01/dns01.go b/mplexer/dns01/dns01.go index 3369818..6ca183a 100644 --- a/mplexer/dns01/dns01.go +++ b/mplexer/dns01/dns01.go @@ -67,12 +67,12 @@ type DNSProvider struct { func NewDNSProvider() (*DNSProvider, error) { values, err := env.Get(EnvEndpoint) if err != nil { - return nil, fmt.Errorf("api: %w", err) + return nil, fmt.Errorf("dns01 api: %w", err) } endpoint, err := url.Parse(values[EnvEndpoint]) if err != nil { - return nil, fmt.Errorf("api: %w", err) + return nil, fmt.Errorf("dns01 api: %w", err) } config := NewDefaultConfig() diff --git a/mplexer/encoder.go b/mplexer/encoder.go index 8248125..eac314a 100644 --- a/mplexer/encoder.go +++ b/mplexer/encoder.go @@ -111,7 +111,7 @@ func (enc *Encoder) Encode(rin io.Reader, src, dst Addr) error { //fmt.Println("[debug] encode payload:", string(b)) _, err = enc.write(header, b) - fmt.Println("[debug] [encoder] [srv] Browser-to-tun write", len(header), header) + fmt.Println("[debug] [encoder] [srv] Browser-to-tun write", len(header), string(header)) fmt.Println("[debug] [encoder] [srv]", len(b), hex.EncodeToString(b)) if nil != err { fmt.Println("[debug] [encoder] [srv] Browser-to-tun write err", err) diff --git a/mplexer/listener.go b/mplexer/listener.go index 72ad11c..6bf2abe 100644 --- a/mplexer/listener.go +++ b/mplexer/listener.go @@ -179,9 +179,9 @@ func (l *Listener) getPipe(src, dst *Addr, count int) net.Conn { newconn.Close() pipe.Close() if nil != err { - fmt.Printf("a stream is done: %q\n", err) + fmt.Printf("[debug] [ln-pipe] encode stream ended:\n%+v\n%+v\n%q\n", *src, *dst, err) } else { - fmt.Printf("a stream is done\n") + fmt.Printf("[debug] [ln-pipe] encode stream ended gracefully:\n%+v\n%+v\n", *src, *dst) } }() diff --git a/mplexer/routemux.go b/mplexer/routemux.go index 3a3cf24..240db6c 100644 --- a/mplexer/routemux.go +++ b/mplexer/routemux.go @@ -18,12 +18,14 @@ type RouteMux struct { routes []meta } +// ErrNotHandled is returned when the next middleware in the stack should take over var ErrNotHandled = errors.New("connection not handled") type meta struct { addr string handler Handler terminate bool + comment string } // NewRouteMux allocates and returns a new RouteMux. @@ -36,6 +38,8 @@ func NewRouteMux() *RouteMux { // Serve dispatches the connection to the handler whose selectors matches the attributes. func (m *RouteMux) Serve(client net.Conn) error { + fmt.Println("\n\n[debug] mux.Serve(client)") + var wconn *ConnWrap switch conn := client.(type) { case *ConnWrap: @@ -54,6 +58,14 @@ func (m *RouteMux) Serve(client net.Conn) error { case *Addr: servername = laddr.Hostname() port = ":" + strconv.Itoa(laddr.Port()) + connServername := wconn.CheckServername() + if "" == connServername { + wconn.SetServername(servername) + } else { + fmt.Printf("Has servername: current=%s new=%s\n", connServername, servername) + wconn.SetServername(servername) + //panic(errors.New("Can't SetServername() over existing servername")) + } default: panic("impossible type switch: Addr is 'tun' but didn't match") } @@ -71,7 +83,7 @@ func (m *RouteMux) Serve(client net.Conn) error { if meta.terminate { servername = wconn.Servername() } - fmt.Println("Meta:", meta.addr, servername) + fmt.Println("\nMeta:", meta.comment, "meta.addr="+meta.addr, "servername="+servername) if servername == meta.addr || "*" == meta.addr || port == meta.addr { //fmt.Println("[debug] test of route:", meta) // Only keep trying handlers if ErrNotHandled was returned @@ -83,32 +95,56 @@ func (m *RouteMux) Serve(client net.Conn) error { fmt.Println("No match found for", wconn.Scheme(), wconn.Servername()) return client.Close() + + // TODO Chi-style route handling + /* + routes := m.routes + next := func() error { + if 0 == len(routes) { + fmt.Println("No match found for", wconn.Scheme(), wconn.Servername()) + return client.Close() + } + route := routes[0] + routes := routes[1:] + handled := false + handler := meta.handler(func () { + if !handled { + handled = true + next() + } + }) + return handler.Serve(client) + } + return next() + */ } // ForwardTCP creates and returns a connection to a local handler target. -func (m *RouteMux) ForwardTCP(servername string, target string, timeout time.Duration) error { +func (m *RouteMux) ForwardTCP(servername string, target string, timeout time.Duration, comment ...string) error { // TODO check servername m.routes = append(m.routes, meta{ addr: servername, terminate: false, handler: NewForwarder(target, timeout), + comment: append(comment, "")[0], }) return nil } // HandleTCP creates and returns a connection to a local handler target. -func (m *RouteMux) HandleTCP(servername string, handler Handler) error { +func (m *RouteMux) HandleTCP(servername string, handler Handler, comment ...string) error { // TODO check servername m.routes = append(m.routes, meta{ addr: servername, terminate: false, handler: handler, + comment: append(comment, "")[0], }) return nil } // HandleTLS creates and returns a connection to a local handler target. -func (m *RouteMux) HandleTLS(servername string, acme *ACME, handler Handler) error { +func (m *RouteMux) HandleTLS(servername string, acme *ACME, next Handler, comment ...string) error { // TODO check servername m.routes = append(m.routes, meta{ addr: servername, @@ -123,16 +159,18 @@ func (m *RouteMux) HandleTLS(servername string, acme *ACME, handler Handler) err } if !wconn.isEncrypted() { - fmt.Println("[debug] conn is not encrypted") + fmt.Println("[debug] HandleTLS: conn is not encrypted") + // TODO handle underlying Peek() timeout error return ErrNotHandled } - fmt.Println("[debug] terminated encrypted connection") + fmt.Println("[debug] HandleTLS: decrypted connection, recursing") //NewTerminator(acme, handler)(client) //return handler.Serve(client) - return handler.Serve(TerminateTLS(wconn, acme)) + return next.Serve(TerminateTLS(wconn, acme)) }), + comment: append(comment, "")[0], }) return nil } diff --git a/mplexer/telebit.go b/mplexer/telebit.go index dac7e25..7da59a1 100644 --- a/mplexer/telebit.go +++ b/mplexer/telebit.go @@ -149,7 +149,7 @@ ForwardData: break ForwardData } if io.EOF != err && io.ErrClosedPipe != err && !strings.Contains(err.Error(), errNetClosing) { - fmt.Printf("read from remote client failed: %q\n", err.Error()) + fmt.Printf("error: data source (websocket client) read failed: %q\n", err.Error()) } else { fmt.Printf("Connection closed (possibly by remote client)\n") } @@ -159,7 +159,7 @@ ForwardData: break ForwardData } if io.EOF != err && io.ErrClosedPipe != err && !strings.Contains(err.Error(), errNetClosing) { - fmt.Printf("read from local target failed: %q\n", err.Error()) + fmt.Printf("error: data sink (local target) read failed: %q\n", err.Error()) } else { fmt.Printf("Connection closed (possibly by local target)\n") } @@ -327,7 +327,9 @@ type Grants struct { } func Inspect(authURL, token string) (*Grants, error) { - msg, err := Request("GET", authURL+"/inspect", token, nil) + inspectURL := authURL + "/inspect" + //fmt.Fprintf(os.Stderr, "[debug] telebit.Inspect(\n\tinspectURL = %s,\n\ttoken = %s,\n)", inspectURL, token) + msg, err := Request("GET", inspectURL, token, nil) if nil != err { return nil, err } diff --git a/mplexer/websockettunnel.go b/mplexer/websockettunnel.go index 5efc8f1..9c318ae 100644 --- a/mplexer/websockettunnel.go +++ b/mplexer/websockettunnel.go @@ -54,6 +54,9 @@ func DialWebsocketTunnel(ctx context.Context, relay, authz string) (net.Conn, er sep = "&" } wsconn, _, err := wsd.DialContext(ctx, relay+sep+"access_token="+authz+"&versions=v1", headers) + if nil != err { + fmt.Println("[debug] [wstun] simple dial failed", err, wsconn, ctx) + } return NewWebsocketTunnel(wsconn), err } @@ -61,15 +64,16 @@ func (wsw *WebsocketTunnel) Read(b []byte) (int, error) { if nil == wsw.tmpr { _, msgr, err := wsw.wsconn.NextReader() if nil != err { - //fmt.Println("debug wsw NextReader err:", err) + fmt.Println("[debug] [wstun] NextReader err:", err) return 0, err } wsw.tmpr = msgr } n, err := wsw.tmpr.Read(b) + fmt.Println("[debug] [wstun] Read", n) if nil != err { - //fmt.Println("debug wsw Read err:", err) + fmt.Println("[debug] [wstun] Read err:", err) if io.EOF == err { wsw.tmpr = nil // ignore the message EOF because it's not the websocket EOF @@ -80,17 +84,18 @@ func (wsw *WebsocketTunnel) Read(b []byte) (int, error) { } func (wsw *WebsocketTunnel) Write(b []byte) (int, error) { + fmt.Println("[debug] [wstun] Write", len(b)) // TODO create or reset ping deadline // TODO document that more complete writes are preferred? msgw, err := wsw.wsconn.NextWriter(websocket.BinaryMessage) if nil != err { - //fmt.Println("debug wsw NextWriter err:", err) + fmt.Println("[debug] [wstun] NextWriter err:", err) return 0, err } n, err := msgw.Write(b) if nil != err { - //fmt.Println("debug wsw Write err:", err) + fmt.Println("[debug] [wstun] Write err:", err) return n, err } @@ -100,7 +105,7 @@ func (wsw *WebsocketTunnel) Write(b []byte) (int, error) { // Close will close the websocket with a control message func (wsw *WebsocketTunnel) Close() error { - //fmt.Println("[debug] closing the websocket.Conn") + fmt.Println("[debug] [wstun] closing the websocket.Conn") // TODO handle EOF as websocket.CloseNormal? message := websocket.FormatCloseMessage(websocket.CloseGoingAway, "closing connection") @@ -138,10 +143,12 @@ func (wsw *WebsocketTunnel) SetDeadline(t time.Time) error { // SetReadDeadline sets the deadline for future Read calls func (wsw *WebsocketTunnel) SetReadDeadline(t time.Time) error { + fmt.Println("[debug] [wstun] read deadline") return wsw.wsconn.SetReadDeadline(t) } // SetWriteDeadline sets the deadline for future Write calls func (wsw *WebsocketTunnel) SetWriteDeadline(t time.Time) error { + fmt.Println("[debug] [wstun] write deadline") return wsw.wsconn.SetWriteDeadline(t) }