yet more logs

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
 }
 

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)
+	b, err := c.Peek(n)
-	fmt.Println("[debug] Peek(n)", b, string(b))
+	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

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]
 			}

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()

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)

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)
 		}
 	}()
 

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
 }

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
 	}

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)
 }