change Windows Start()/Stop() behavior, update debug output

cmd/telebit/telebit.go

@@ -162,21 +162,27 @@ func (p *program) Init(env svc.Environment) error {
 
 		os.Stdout = f
 		os.Stderr = f
+		dbg.OutFile = f
+		dbg.ErrFile = f
 		log.SetOutput(f)
 	}
 
 	return nil
 }
 
+var started bool
+
 func (p *program) Start() error {
 	log.Printf("Starting...\n")
+	if !started {
+		started = true
 		go fetchDirectivesAndRun()
+	}
 	return nil
 }
 
 func (p *program) Stop() error {
-	log.Printf("Can't stop. Exiting instead.\n")
-	os.Exit(exitOk)
+	log.Printf("Can't stop. Doing nothing instead.\n")
 	return nil
 }
 
@@ -202,7 +208,7 @@ func parseFlagsAndENVs() {
 	var resolvers []string
 	var dnsPropagationDelay time.Duration
 
-	debug := flag.Bool("debug", true, "show debug output")
+	debug := flag.Bool("debug", false, "show debug output")
 	verbose := flag.Bool("verbose", false, "log excessively")
 
 	spfDomain := flag.String("spf-domain", "", "domain with SPF-like list of IP addresses which are allowed to connect to clients")
@@ -237,10 +243,6 @@ func parseFlagsAndENVs() {
 
 	flag.Parse()
 
-	if !dbg.Debug {
-		dbg.Debug = *verbose || *debug
-	}
-
 	if len(*envpath) > 0 {
 		if err := godotenv.Load(*envpath); nil != err {
 			fmt.Fprintf(os.Stderr, "%v", err)
@@ -248,6 +250,21 @@ func parseFlagsAndENVs() {
 			return
 		}
 	}
+	dbg.Init()
+
+	if !dbg.Verbose {
+		if *verbose {
+			dbg.Verbose = true
+			dbg.Printf("--verbose: extra output enabled")
+		}
+	}
+	if !dbg.Debug {
+		if *debug {
+			dbg.Verbose = true
+			dbg.Debug = true
+			dbg.Printf("--debug: byte output will be printed in full as hex")
+		}
+	}
 
 	spfRecords := iplist.Init(*spfDomain)
 	if len(spfRecords) > 0 {

internal/dbg/dbg.go

@@ -4,50 +4,141 @@ import (
 	"encoding/hex"
 	"fmt"
 	"os"
+	"strings"
 )
 
-// Debug is a flag for whether or not verbose logging should be activated
+// Verbose is a flag for whether or not verbose logging should be activated
+var Verbose bool
+
+// Debug does not truncate byte strings
 var Debug bool
 
-var rawBytes bool
-var allBytes bool
+// VerboseVerbose does not truncate strings
+var VerboseVerbose bool
+
+// OutFile is the output path for StdOut
+var OutFile *os.File
+
+// ErrFile is the output path for StdErr
+var ErrFile *os.File
+
+type out int
+
+const (
+	stdout out = iota
+	stderr
+)
+
+type output struct {
+	out   out
+	msg   string
+	other []interface{}
+}
+
+var log chan output
 
 func init() {
+	log = make(chan output)
+
 	Init()
+
+	go func() {
+		for {
+			o := <-log
+			// because OutFile and ErrFile may be the same
+			msg := strings.TrimSuffix(o.msg, "\n") + "\n"
+			b := []byte(fmt.Sprintf(msg, o.other...))
+			if stdout == o.out {
+				OutFile.Write(b)
+			} else {
+				ErrFile.Write(b)
+			}
+		}
+	}()
+}
+
+// Printf will print to log.Printf
+func Printf(tpl string, other ...interface{}) {
+	log <- output{
+		out:   stdout,
+		msg:   tpl,
+		other: other,
+	}
+}
+
+// Warnf will print to fmt.Fprintf(stderr)
+func Warnf(tpl string, other ...interface{}) {
+	log <- output{
+		out:   stderr,
+		msg:   "[warn] " + tpl,
+		other: other,
+	}
+}
+
+// Debugf will print to fmt.Fprintf(std)
+func Debugf(tpl string, other ...interface{}) {
+	log <- output{
+		out:   stderr,
+		msg:   "[debug] " + tpl,
+		other: other,
+	}
 }
 
 // Init will set debug vars from ENVs and print out whatever is set
 func Init() {
-	if !Debug {
-		Debug = ("true" == os.Getenv("VERBOSE"))
+	if nil == OutFile {
+		OutFile = os.Stdout
 	}
-	if !allBytes {
-		allBytes = ("true" == os.Getenv("VERBOSE_BYTES"))
-	}
-	if !rawBytes {
-		rawBytes = ("true" == os.Getenv("VERBOSE_RAW"))
+	if nil == ErrFile {
+		ErrFile = os.Stderr
 	}
 
+	if !Verbose {
+		if "true" == os.Getenv("VERBOSE") {
+			Printf("VERBOSE=true")
+			Verbose = true
+		}
+		if Verbose {
+			fmt.Fprintf(os.Stderr, "VERBOSE: extra logging enabled\n")
+		}
+	}
+
+	if !VerboseVerbose {
+		if "true" == strings.ToLower(os.Getenv("VERBOSE_VERBOSE")) {
+			Printf("VERBOSE_VERBOSE=true")
+			VerboseVerbose = true
+		} else if "true" == strings.ToLower(os.Getenv("VERBOSE_RAW")) {
+			Printf("VERBOSE_RAW=true # Deprecated: Use VERBOSE_VERBOSE=true")
+			VerboseVerbose = true
+		}
+		if VerboseVerbose {
+			fmt.Fprintf(os.Stderr, "VERBOSE_VERBOSE: output will NOT be truncated\n")
+		}
+	}
+
+	if !Debug {
+		if "true" == strings.ToLower(os.Getenv("DEBUG")) {
+			Printf("DEBUG=true")
+			Debug = true
+		} else if "true" == strings.ToLower(os.Getenv("VERBOSE_BYTES")) {
+			Printf("VERBOSE_BYTES=true # Deprecated: Use DEBUG=true")
+			Debug = true
+		}
 		if Debug {
-		fmt.Fprintf(os.Stderr, "DEBUG=true\n")
+			fmt.Fprintf(os.Stderr, "DEBUG: byte output will be printed as hex\n")
 		}
-	if allBytes || rawBytes {
-		fmt.Fprintf(os.Stderr, "VERBOSE_BYTES=true\n")
-	}
-	if rawBytes {
-		fmt.Fprintf(os.Stderr, "VERBOSE_RAW=true\n")
 	}
 }
 
 // Trunc will take up to the first and last 20 bytes of the input to product 80 char hex output
 func Trunc(b []byte, n int) string {
 	bin := b[:n]
-	if allBytes || rawBytes {
-		if rawBytes {
-			return string(bin)
-		}
+	if Debug || VerboseVerbose {
+		if Debug {
 			return hex.EncodeToString(bin)
 		}
+		return string(bin)
+	}
 	if n > 40 {
 		return hex.EncodeToString(bin[:19]) + ".." + hex.EncodeToString(bin[n-19:])
 	}

internal/sni/sni.go

@@ -6,14 +6,33 @@ import (
 	"errors"
 )
 
+// ErrNotClientHello happens when the TLS packet is not a ClientHello
+var ErrNotClientHello = errors.New("Not a ClientHello")
+
+// ErrMalformedHello is a failure to parse the ClientHello
+var ErrMalformedHello = errors.New("malformed TLS ClientHello")
+
+// ErrNoExtensions means that SNI is missing from the ClientHello
+var ErrNoExtensions = errors.New("no TLS extensions")
+
 // GetHostname uses SNI to determine the intended target of a new TLS connection.
-func GetHostname(b []byte) (string, error) {
+func GetHostname(b []byte) (hostname string, err error) {
+	// Since this is a hot piece of code (runs frequently)
+	// we protect against out-of-bounds reads with recover
+	// rather than adding additional out-of-bounds checks
+	// in addition to the ones that Go already provides
+	defer func() {
+		if r := recover(); nil != r {
+			err = ErrMalformedHello
+		}
+	}()
 	rest := b[5:]
+	n := len(rest)
 	current := 0
 	handshakeType := rest[0]
 	current++
 	if handshakeType != 0x1 {
-		return "", errors.New("Not a ClientHello")
+		return "", ErrNotClientHello
 	}
 
 	// Skip over another length
@@ -35,14 +54,14 @@ func GetHostname(b []byte) (string, error) {
 	current++
 	current += compressionMethodLength
 
-	if current > len(rest) {
-		return "", errors.New("no extensions")
+	// TODO shouldn't this be current >= n ??
+	if current > n {
+		return "", ErrNoExtensions
 	}
 
 	current += 2
 
-	hostname := ""
-	for current < len(rest) && hostname == "" {
+	for current < n {
 		extensionType := (int(rest[current]) << 8) + int(rest[current+1])
 		current += 2
 

internal/telebit/connwrap.go

@@ -2,9 +2,8 @@ package telebit
 
 import (
 	"bufio"
-	"fmt"
+	"encoding/hex"
 	"net"
-	"os"
 	"time"
 
 	"git.rootprojects.org/root/telebit/internal/dbg"
@@ -139,14 +138,14 @@ func (c *ConnWrap) isEncrypted() bool {
 	c.SetDeadline(time.Now().Add(5 * time.Second))
 	n := 6
 	b, err := c.Peek(n)
+	defer c.SetDeadline(time.Time{})
 	if dbg.Debug {
-		fmt.Fprintf(os.Stderr, "[debug] [wrap] Peek(%d): %s %v\n", n, string(b), err)
+		dbg.Debugf("[wrap] Peek(%d): %q %v\n", n, hex.EncodeToString(b), err)
 	}
 	if nil != err {
 		// TODO return error on error?
 		return encrypted
 	}
-	defer c.SetDeadline(time.Time{})
 	if len(b) >= n {
 		// SSL v3.x / TLS v1.x
 		// 0: TLS Byte

internal/telebit/routemux.go

@@ -120,7 +120,7 @@ func (m *RouteMux) Serve(client net.Conn) error {
 		}
 	}
 
-	fmt.Printf("No match found for %q %q\n", wconn.Scheme(), wconn.Servername())
+	fmt.Printf("No match found for scheme=%q servername=%q\n", wconn.Scheme(), wconn.Servername())
 	return client.Close()
 
 	// TODO Chi-style route handling