diff --git a/connwrap.go b/connwrap.go index 2e7c19f..7a2d787 100644 --- a/connwrap.go +++ b/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? diff --git a/decoder.go b/decoder.go index 1eca398..9d4cda7 100644 --- a/decoder.go +++ b/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() diff --git a/encoder.go b/encoder.go index 03b5a8d..6a4813d 100644 --- a/encoder.go +++ b/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.Println("[debug] encode payload:", string(b)) + //fmt.Fprintf(os.Stderr, "[debug] encode header: %s\n", string(header)) + //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.Println("[debug] [encoder] [srv]", len(b), dbg.Trunc(b, len(b))) + fmt.Fprintf(os.Stderr, "[debug] [encoder] [srv] Browser-to-tun write %d %s\n", len(header), strings.TrimSpace(string(header))) + 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 diff --git a/listener.go b/listener.go index 6bf2abe..bd2863d 100644 --- a/listener.go +++ b/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) } }() diff --git a/mgmt/auth.go b/mgmt/auth.go index ddb2542..32f8ca1 100644 --- a/mgmt/auth.go +++ b/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 { diff --git a/parser.go b/parser.go index afc9d74..935c605 100644 --- a/parser.go +++ b/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: diff --git a/routemux.go b/routemux.go index 1bfe270..ece7d86 100644 --- a/routemux.go +++ b/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) diff --git a/table/table.go b/table/table.go index cd5d131..4606efa 100644 --- a/table/table.go +++ b/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 } diff --git a/telebit.go b/telebit.go index 1b5125d..6656edc 100644 --- a/telebit.go +++ b/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(), diff --git a/v1.go b/v1.go index 3bb0f1d..9ace3b4 100644 --- a/v1.go +++ b/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) - fmt.Printf("[debug] unpackV1 RouteBytes: %#v %#v %s\n", p.state.srcAddr, p.state.dstAddr, p.state.dstAddr.scheme) + if dbg.Debug { + //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{}