debug cleanup

connwrap.go

@@ -4,6 +4,7 @@ import (
 	"bufio"
 	"fmt"
 	"net"
+	"os"
 	"time"
 
 	"git.rootprojects.org/root/telebit/dbg"
@@ -139,7 +140,7 @@ func (c *ConnWrap) isEncrypted() bool {
 	n := 6
 	b, err := c.Peek(n)
 	if dbg.Debug {
-		fmt.Printf("[debug] [wrap] Peek(%d): %s %v\n", n, string(b), err)
+		fmt.Fprintf(os.Stderr, "[debug] [wrap] Peek(%d): %s %v\n", n, string(b), err)
 	}
 	if nil != err {
 		// TODO return error on error?

decoder.go

@@ -3,7 +3,7 @@ package telebit
 import (
 	"fmt"
 	"io"
-	"log"
+	"os"
 
 	"git.rootprojects.org/root/telebit/dbg"
 )
@@ -35,13 +35,13 @@ func (d *Decoder) Decode(out Router) error {
 			b := make([]byte, d.bufferSize)
 			n, err := d.in.Read(b)
 			if dbg.Debug {
-				log.Println("[debug] [decoder] [srv] Tunnel read", n, dbg.Trunc(b, n))
+				fmt.Fprintf(os.Stderr, "[debug] [decoder] [srv] Tunnel read %d %s\n", n, dbg.Trunc(b, n))
 			}
 			if n > 0 {
 				rx <- b[:n]
 			}
 			if nil != err {
-				fmt.Println("[debug] [decoder] [srv] Tunnel read err", err)
+				fmt.Fprintf(os.Stderr, "[decoder] [srv] Tunnel read err: %s\n", err)
 				rxErr <- err
 				return
 			}
@@ -53,11 +53,11 @@ func (d *Decoder) Decode(out Router) error {
 		case b := <-rx:
 			n, err := p.Write(b)
 			if dbg.Debug {
-				fmt.Println("[debug] [decoder] [srv] Tunnel write", n, len(b), dbg.Trunc(b, len(b)))
+				fmt.Fprintf(os.Stderr, "[debug] [decoder] [srv] Tunnel write %d %d %s\n", n, len(b), dbg.Trunc(b, len(b)))
 			}
 			// TODO BUG: handle when 'n' bytes written is less than len(b)
 			if nil != err {
-				fmt.Println("[debug] [decoder] [srv] Tunnel write error")
+				fmt.Fprintf(os.Stderr, "[decoder] [srv] Tunnel write err: %s\n", err)
 				// an error to write represents an unrecoverable error,
 				// not just a downstream client error
 				//d.in.Close()

encoder.go

@@ -5,6 +5,7 @@ import (
 	"errors"
 	"fmt"
 	"io"
+	"os"
 	"strings"
 	"sync"
 
@@ -68,7 +69,7 @@ func (enc *Encoder) Encode(rin io.Reader, src, dst Addr) error {
 	rx := make(chan []byte)
 	rxErr := make(chan error)
 
-	//fmt.Println("[debug] what's the source to encode?", src)
+	//fmt.Fprintf(os.Stderr, "[debug] what's the source to encode? %v\n", src)
 
 	go func() {
 		for {
@@ -76,13 +77,15 @@ func (enc *Encoder) Encode(rin io.Reader, src, dst Addr) error {
 			//fmt.Println("loopers gonna loop")
 			n, err := rin.Read(b)
 			if dbg.Debug {
-				fmt.Println("[debug] [encoder] [srv] Browser read", n, dbg.Trunc(b, n))
+				fmt.Fprintf(os.Stderr, "[debug] [encoder] [srv] Browser read %d %s\n", n, dbg.Trunc(b, n))
 			}
 			if n > 0 {
 				rx <- b[:n]
 			}
 			if nil != err {
-				fmt.Println("[debug] [encoder] [srv] Browser read error", err)
+				if io.EOF != err {
+					fmt.Fprintf(os.Stderr, "[encoder] [srv] Browser read err: %s\n", err)
+				}
 				rxErr <- err
 				return
 			}
@@ -99,32 +102,32 @@ func (enc *Encoder) Encode(rin io.Reader, src, dst Addr) error {
 			// TODO: verify that closing the reader will cause the goroutine to be released
 			//rin.Close()
 			if dbg.Debug {
-				fmt.Println("[debug] [encoder] [srv] Browser ctx.Done()")
+				fmt.Fprintf(os.Stderr, "[debug] [encoder] [srv] Browser ctx.Done()\n")
 			}
 			return errors.New("cancelled by encoder read or parent context")
 		/*
 			case <-enc.subctx.Done():
 				//rin.Close()
-				fmt.Println("[debug] [encoder] [srv] Browser subctx.Done()")
+				fmt.Fprintf(os.Stderr, "[debug] [encoder] [srv] Browser subctx.Done()\n")
 				return errors.New("cancelled by encoder write context")
 		*/
 		case b := <-rx:
 			header, _, err := Encode(b, src, Addr{scheme: src.scheme, addr: dst.Hostname(), port: dst.Port()})
 			if nil != err {
 				//rin.Close()
-				fmt.Println("[debug] [encoder] [srv] Browser Encode err", err)
+				fmt.Fprintf(os.Stderr, "[encoder] [srv] Browser Encode err: %s\n", err)
 				return err
 			}
-			//fmt.Println("[debug] encode header:", string(header))
+			//fmt.Fprintf(os.Stderr, "[debug] encode header: %s\n", string(header))
-			//fmt.Println("[debug] encode payload:", string(b))
+			//fmt.Fprintf(os.Stderr, "[debug] encode payload: %s\n", string(b))
 
 			_, err = enc.write(header, b)
 			if dbg.Debug {
-				fmt.Println("[debug] [encoder] [srv] Browser-to-tun write", len(header), strings.TrimSpace(string(header)))
+				fmt.Fprintf(os.Stderr, "[debug] [encoder] [srv] Browser-to-tun write %d %s\n", len(header), strings.TrimSpace(string(header)))
-				fmt.Println("[debug] [encoder] [srv]", len(b), dbg.Trunc(b, len(b)))
+				fmt.Fprintf(os.Stderr, "[debug] [encoder] [srv] %d %s\n", len(b), dbg.Trunc(b, len(b)))
 			}
 			if nil != err {
-				fmt.Println("[debug] [encoder] [srv] Browser-to-tun write err", err)
+				fmt.Fprintf(os.Stderr, "[encoder] [srv] Browser-to-tun write err: %s\n", err)
 				//rin.Close()
 				return err
 			}
@@ -133,7 +136,7 @@ func (enc *Encoder) Encode(rin io.Reader, src, dst Addr) error {
 			//rin.Close()
 			if io.EOF == err {
 				header, _, _ := Encode(nil, src, Addr{scheme: "end"})
-				//fmt.Println("[debug] encode end: ", string(header))
+				//fmt.Fprintf(os.Stderr, "[debug] encode end: %s\n", string(header))
 				// ignore err, which may have already closed
 				_, _ = enc.write(header, nil)
 				return nil

listener.go

@@ -6,7 +6,10 @@ import (
 	"io"
 	"net"
 	"net/http"
+	"os"
 	"strings"
+
+	"git.rootprojects.org/root/telebit/dbg"
 )
 
 // A Listener transforms a multiplexed websocket connection into individual net.Conn-like connections.
@@ -83,7 +86,7 @@ func Serve(listener net.Listener, mux Handler) error {
 				if io.EOF != err && io.ErrClosedPipe != err && !strings.Contains(err.Error(), errNetClosing) {
 					fmt.Printf("client could not be served: %q\n", err.Error())
 				}
-				fmt.Println("[debug] closing original client", err)
+				fmt.Printf("closing original client: %s\n", err)
 				client.Close()
 			}
 		}()
@@ -142,7 +145,9 @@ func (l *Listener) RouteBytes(srcAddr, dstAddr Addr, b []byte) {
 	}
 	// EOF, if needed
 	if "end" == string(dst.scheme) {
-		fmt.Println("[debug] end")
+		if dbg.Debug {
+			fmt.Fprintf(os.Stderr, "[debug] end\n")
+		}
 		pipe.Close()
 		delete(l.conns, src.String())
 	}
@@ -179,9 +184,9 @@ func (l *Listener) getPipe(src, dst *Addr, count int) net.Conn {
 		newconn.Close()
 		pipe.Close()
 		if nil != err {
-			fmt.Printf("[debug] [ln-pipe] encode stream ended:\n%+v\n%+v\n%q\n", *src, *dst, err)
+			fmt.Fprintf(os.Stderr, "[debug] [ln-pipe] encode stream ended:\n%+v\n%+v\n%q\n", *src, *dst, err)
 		} else {
-			fmt.Printf("[debug] [ln-pipe] encode stream ended gracefully:\n%+v\n%+v\n", *src, *dst)
+			fmt.Fprintf(os.Stderr, "[debug] [ln-pipe] encode stream ended gracefully:\n%+v\n%+v\n", *src, *dst)
 		}
 	}()
 

mgmt/auth.go

@@ -5,10 +5,11 @@ import (
 	"encoding/json"
 	"fmt"
 	"io/ioutil"
+	"os"
 
+	telebit "git.rootprojects.org/root/telebit"
 	"git.rootprojects.org/root/telebit/dbg"
 	"git.rootprojects.org/root/telebit/mgmt/authstore"
-	telebit "git.rootprojects.org/root/telebit"
 )
 
 type SuccessResponse struct {
@@ -40,7 +41,7 @@ func Register(authURL, secret, ppid string) (kid string, err error) {
 	jsonb := bytes.NewBuffer([]byte(jsons))
 	fullURL := authURL + "/register-device/" + secret
 	if dbg.Debug {
-		fmt.Println("[debug] authURL, secret, ppid", fullURL, secret, jsons)
+		fmt.Fprintf(os.Stderr, "[debug] authURL=%s, secret=%s, ppid=%s\n", fullURL, secret, jsons)
 	}
 	msg, err := telebit.Request("POST", fullURL, "", jsonb)
 	if nil != err {

parser.go

@@ -3,6 +3,7 @@ package telebit
 import (
 	"errors"
 	"fmt"
+	"os"
 
 	"git.rootprojects.org/root/telebit/dbg"
 )
@@ -72,7 +73,7 @@ func (p *Parser) Write(b []byte) (int, error) {
 	switch p.parseState {
 	case VersionState:
 		if dbg.Debug {
-			fmt.Println("[debug] MPLEXY version byte", b[0], string(b))
+			fmt.Fprintf(os.Stderr, "[debug] MPLEXY version byte %v %s", b[0], string(b))
 		}
 		p.state.version = b[0]
 		b = b[1:]
@@ -85,7 +86,7 @@ func (p *Parser) Write(b []byte) (int, error) {
 	switch p.state.version {
 	case V1:
 		if dbg.Debug {
-			fmt.Println("[debug] MPLEXY packet is of type v1")
+			fmt.Fprintf(os.Stderr, "[debug] MPLEXY packet is of type v1\n")
 		}
 		return p.unpackV1(b)
 	default:

routemux.go

@@ -4,9 +4,12 @@ import (
 	"errors"
 	"fmt"
 	"net"
+	"os"
 	"strconv"
 	"strings"
 	"time"
+
+	"git.rootprojects.org/root/telebit/dbg"
 )
 
 // A RouteMux is a net.Conn multiplexer.
@@ -38,7 +41,9 @@ 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)")
+	if dbg.Debug {
+		fmt.Fprintf(os.Stderr, "\n\n[debug] mux.Serve(client)\n")
+	}
 
 	var wconn *ConnWrap
 	switch conn := client.(type) {
@@ -85,7 +90,7 @@ func (m *RouteMux) Serve(client net.Conn) error {
 		}
 		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)
+			//fmt.Fprintf(os.Stderr, "[debug] test of route: %v\n", meta)
 			// Only keep trying handlers if ErrNotHandled was returned
 			if err := meta.handler.Serve(wconn); ErrNotHandled != err {
 				return err
@@ -159,12 +164,16 @@ func (m *RouteMux) HandleTLS(servername string, acme *ACME, next Handler, commen
 			}
 
 			if !wconn.isEncrypted() {
-				fmt.Println("[debug] HandleTLS: conn is not encrypted")
+				if dbg.Debug {
+					fmt.Fprintf(os.Stderr, "[debug] HandleTLS: conn is not encrypted\n")
+				}
 				// TODO handle underlying Peek() timeout error
 				return ErrNotHandled
 			}
 
-			fmt.Println("[debug] HandleTLS: decrypted connection, recursing")
+			if dbg.Debug {
+				fmt.Fprintf(os.Stderr, "[debug] HandleTLS: decrypted connection, recursing\n")
+			}
 
 			//NewTerminator(acme, handler)(client)
 			//return handler.Serve(client)

table/table.go

@@ -3,14 +3,15 @@ package table
 import (
 	"fmt"
 	"net"
+	"os"
 	"sync"
 
 	"io"
 	"strconv"
 	"strings"
 
-	"git.rootprojects.org/root/telebit/dbg"
 	telebit "git.rootprojects.org/root/telebit"
+	"git.rootprojects.org/root/telebit/dbg"
 	"github.com/gorilla/websocket"
 )
 
@@ -53,13 +54,17 @@ func Add(server *SubscriberConn) {
 func RemoveServer(server *SubscriberConn) bool {
 	// TODO remove by RemoteAddr
 	//return false
-	fmt.Printf("[warn] RemoveServer() still calls Remove(subject) instead of removing by RemoteAddr\n")
+	fmt.Fprintf(
+		os.Stderr,
+		"[warn] RemoveServer() still calls Remove(subject) instead of removing by RemoteAddr\n",
+	)
 	return Remove(server.Grants.Subject)
 }
 
 func Remove(subject string) bool {
 	srvMapX, ok := Servers.Load(subject)
-	fmt.Printf("[debug] has server for %s? %t\n", subject, ok)
+	fmt.Printf("Remove(%s): exists? %t\n", subject, ok)
+
 	if !ok {
 		return false
 	}
@@ -115,20 +120,24 @@ type SubscriberConn struct {
 func (s *SubscriberConn) RouteBytes(src, dst telebit.Addr, payload []byte) {
 	id := fmt.Sprintf("%s:%d", src.Hostname(), src.Port())
 	if dbg.Debug {
-		fmt.Println("[debug] Routing some more bytes:", dbg.Trunc(payload, len(payload)))
+		fmt.Fprintf(
+			os.Stderr,
+			"[debug] Routing some more bytes: %s\n",
+			dbg.Trunc(payload, len(payload)),
+		)
+		fmt.Printf("\tid %s\nsrc %+v\n", id, src)
+		fmt.Printf("\tdst %s %+v\n", dst.Scheme(), dst)
 	}
-	fmt.Printf("id %s\nsrc %+v\n", id, src)
-	fmt.Printf("dst %s %+v\n", dst.Scheme(), dst)
 	clientX, ok := s.Clients.Load(id)
 	if !ok {
 		// TODO send back closed client error
-		fmt.Println("[debug] no client found for", id)
+		fmt.Printf("RouteBytes({ %s }, %v, ...) [debug] no client found for %s\n", id, dst)
 		return
 	}
 
 	client, _ := clientX.(net.Conn)
 	if "end" == dst.Scheme() {
-		fmt.Println("[debug] closing client", id)
+		fmt.Printf("RouteBytes: { %s }.Close(): %v\n", id, dst)
 		_ = client.Close()
 		return
 	}
@@ -136,7 +145,7 @@ func (s *SubscriberConn) RouteBytes(src, dst telebit.Addr, payload []byte) {
 	for {
 		n, err := client.Write(payload)
 		if dbg.Debug {
-			fmt.Println("[debug] table Write", dbg.Trunc(payload, len(payload)))
+			fmt.Fprintf(os.Stderr, "[debug] table Write %s\n", dbg.Trunc(payload, len(payload)))
 		}
 		if nil == err || io.EOF == err {
 			break
@@ -162,10 +171,12 @@ func (s *SubscriberConn) Serve(client net.Conn) error {
 	}
 
 	id := client.RemoteAddr().String()
-	fmt.Printf("[DEBUG] NEW ID (ip:port) %s\n", id)
+	if dbg.Debug {
+		fmt.Fprintf(os.Stderr, "[debug] NEW ID (ip:port) %s\n", id)
+	}
 	s.Clients.Store(id, client)
 
-	//fmt.Println("[debug] immediately cancel client to simplify testing / debugging")
+	//fmt.Fprintf(os.Stderr, "[debug] immediately cancel client to simplify testing / debugging\n")
 	//_ = client.Close()
 
 	// TODO
@@ -176,12 +187,16 @@ func (s *SubscriberConn) Serve(client net.Conn) error {
 	srcParts := strings.Split(client.RemoteAddr().String(), ":")
 	srcAddr := srcParts[0]
 	srcPort, _ := strconv.Atoi(srcParts[1])
-	fmt.Println("[debug] srcParts", srcParts)
 
 	dstParts := strings.Split(client.LocalAddr().String(), ":")
 	dstAddr := dstParts[0]
 	dstPort, _ := strconv.Atoi(dstParts[1])
-	fmt.Println("[debug] dstParts", dstParts)
+
+	if dbg.Debug {
+		fmt.Fprintf(os.Stderr, "[debug] srcParts %v\n", srcParts)
+		fmt.Fprintf(os.Stderr, "[debug] dstParts %v\n", dstParts)
+	}
+
 	servername := wconn.Servername()
 
 	termination := telebit.Unknown
@@ -210,12 +225,18 @@ func (s *SubscriberConn) Serve(client net.Conn) error {
 		dstAddr,
 		dstPort,
 	)
-	fmt.Printf("[debug] NewAddr src %+v\n", src)
+
-	fmt.Printf("[debug] NewAddr dst %+v\n", dst)
+	if dbg.Debug {
+		fmt.Fprintf(os.Stderr, "[debug] NewAddr src %+v\n", src)
+		fmt.Fprintf(os.Stderr, "[debug] NewAddr dst %+v\n", dst)
+	}
 
 	err := s.MultiEncoder.Encode(wconn, *src, *dst)
 	_ = wconn.Close()
-	fmt.Printf("[debug] Encoder Complete %+v %+v\n", id, err)
+
+	if dbg.Debug {
+		fmt.Fprintf(os.Stderr, "[debug] Encoder Complete %+v %+v\n", id, err)
+	}
 	s.Clients.Delete(id)
 	return err
 }

telebit.go

@@ -116,7 +116,7 @@ func Forward(client net.Conn, target net.Conn, timeout time.Duration) error {
 	}()
 
 	fmt.Println(
-		"[debug] forwarding tcp connection",
+		"Forwarding TCP connection",
 		client.LocalAddr(),
 		client.RemoteAddr(),
 		target.LocalAddr(),

v1.go

@@ -3,6 +3,7 @@ package telebit
 import (
 	"errors"
 	"fmt"
+	"os"
 	"strconv"
 	"strings"
 
@@ -52,7 +53,9 @@ func (p *Parser) unpackV1(b []byte) (int, error) {
 		z++
 		n := len(b)
 		if n < 1 {
-			fmt.Printf("[debug] v1 message unpacked (%d loops) (%d bytes left)\n", z, n)
+			if dbg.Debug {
+				fmt.Fprintf(os.Stderr, "[debug] v1 message unpacked (%d loops) (%d bytes left)\n", z, n)
+			}
 			break
 		}
 
@@ -90,7 +93,7 @@ func (p *Parser) unpackV1(b []byte) (int, error) {
 				return consumed, err
 			}
 		default:
-			fmt.Println("[debug] v1 unknown state")
+			fmt.Fprintf(os.Stderr, "[debug] v1 unknown state\n")
 			// do nothing
 			consumed := p.consumed
 			p.consumed = 0
@@ -142,9 +145,13 @@ func (p *Parser) unpackV1Header(b []byte, n int) ([]byte, error) {
 	port, _ := strconv.Atoi(parts[PortIndex])
 	service := parts[ServiceIndex]
 
-	fmt.Printf("[debug] parts: %s\n", strings.Join(parts, " | "))
+	if dbg.Debug {
+		fmt.Fprintf(os.Stderr, "[debug] parts: %s\n", strings.Join(parts, " | "))
+	}
 	if "control" == service {
-		fmt.Printf("[debug] control: %s\n", service)
+		if dbg.Debug {
+			fmt.Fprintf(os.Stderr, "[debug] control: %s\n", service)
+		}
 		return nil, errors.New("'control' messages not implemented")
 	}
 
@@ -185,7 +192,7 @@ func (p *Parser) unpackV1Header(b []byte, n int) ([]byte, error) {
 	*/
 	p.parseState++
 	if dbg.Debug {
-		fmt.Printf("[debug] unpackV1 parse state: %v\n", p.parseState)
+		fmt.Fprintf(os.Stderr, "[debug] unpackV1 parse state: %v\n", p.parseState)
 	}
 
 	if "end" == service {
@@ -197,7 +204,7 @@ func (p *Parser) unpackV1Header(b []byte, n int) ([]byte, error) {
 
 func (p *Parser) unpackV1Payload(b []byte, n int) ([]byte, error) {
 	if dbg.Debug {
-		fmt.Printf("[debug] unpackV1 payload state: %+v\n", p.state)
+		fmt.Fprintf(os.Stderr, "[debug] unpackV1 payload state: %+v\n", p.state)
 	}
 	// Handle "connect" and "end"
 	if 0 == p.state.payloadLen {
@@ -216,8 +223,10 @@ func (p *Parser) unpackV1Payload(b []byte, n int) ([]byte, error) {
 			return b, nil
 		*/
 
-		//fmt.Printf("[debug] [2] payload written: %d | payload length: %d\n", p.state.payloadWritten, p.state.payloadLen)
+		if dbg.Debug {
-		fmt.Printf("[debug] unpackV1 RouteBytes: %#v %#v %s\n", p.state.srcAddr, p.state.dstAddr, p.state.dstAddr.scheme)
+			//fmt.Fprintf(os.Stderr, "[debug] [2] payload written: %d | payload length: %d\n", p.state.payloadWritten, p.state.payloadLen)
+			fmt.Fprintf(os.Stderr, "[debug] unpackV1 RouteBytes: %#v %#v %s\n", p.state.srcAddr, p.state.dstAddr, p.state.dstAddr.scheme)
+		}
 		p.handler.RouteBytes(p.state.srcAddr, p.state.dstAddr, []byte{})
 		return b, nil
 	}
@@ -242,7 +251,7 @@ func (p *Parser) unpackV1Payload(b []byte, n int) ([]byte, error) {
 	p.consumed += k
 	p.state.payloadWritten += k
 
-	//fmt.Printf("[debug] [1] payload written: %d | payload length: %d\n", p.state.payloadWritten, p.state.payloadLen)
+	//fmt.Fprintf(os.Stderr, "[debug] [1] payload written: %d | payload length: %d\n", p.state.payloadWritten, p.state.payloadLen)
 	// if this payload is complete, reset all state
 	if p.state.payloadWritten == p.state.payloadLen {
 		p.state = ParserState{}