replace log with slog

Android/app/src/go/backend/tunnel.go

@@ -20,8 +20,8 @@ import (
 	"io/fs"
 	"localhost/Intra/Android/app/src/go/intra"
 	"localhost/Intra/Android/app/src/go/intra/protect"
+	"localhost/Intra/Android/app/src/go/logging"
 	"localhost/Intra/Android/app/src/go/tuntap"
-	"log"
 	"os"
 
 	"github.com/Jigsaw-Code/outline-sdk/network"
@@ -74,8 +74,8 @@ func ConnectSession(
 }
 
 func copyUntilEOF(dst, src io.ReadWriteCloser) {
-	log.Printf("[debug] start relaying traffic [%s] -> [%s]", src, dst)
-	defer log.Printf("[debug] stop relaying traffic [%s] -> [%s]", src, dst)
+	logging.Dbg("IntraSession(copyUntilEOF) - start relaying traffic", "src", src, "dst", dst)
+	defer logging.Dbg("IntraSession(copyUntilEOF) - stop relaying traffic", "src", src, "dst", dst)
 
 	const commonMTU = 1500
 	buf := make([]byte, commonMTU)

Android/app/src/go/doh/client_auth.go

@@ -21,7 +21,6 @@ import (
 	"crypto/x509"
 	"errors"
 	"io"
-
 	"localhost/Intra/Android/app/src/go/logging"
 )
 
@@ -52,12 +51,12 @@ type clientAuthWrapper struct {
 func (ca *clientAuthWrapper) GetClientCertificate(
 	info *tls.CertificateRequestInfo) (*tls.Certificate, error) {
 	if ca.signer == nil {
-		logging.Warn.Println("Client certificate requested but not supported")
+		logging.Warn("Client certificate requested but not supported")
 		return &tls.Certificate{}, nil
 	}
 	cert := ca.signer.GetClientCertificate()
 	if cert == nil {
-		logging.Warn.Println("Unable to fetch client certificate")
+		logging.Warn("Unable to fetch client certificate")
 		return &tls.Certificate{}, nil
 	}
 	chain := [][]byte{cert}
@@ -67,13 +66,13 @@ func (ca *clientAuthWrapper) GetClientCertificate(
 	}
 	leaf, err := x509.ParseCertificate(cert)
 	if err != nil {
-		logging.Warn.Printf("Unable to parse client certificate: %v\n", err)
+		logging.Warnf("Unable to parse client certificate: %v", err)
 		return &tls.Certificate{}, nil
 	}
 	_, isECDSA := leaf.PublicKey.(*ecdsa.PublicKey)
 	if !isECDSA {
 		// RSA-PSS and RSA-SSA both need explicit signature generation support.
-		logging.Warn.Println("Only ECDSA client certificates are supported")
+		logging.Warn("Only ECDSA client certificates are supported")
 		return &tls.Certificate{}, nil
 	}
 	return &tls.Certificate{
@@ -91,7 +90,7 @@ func (ca *clientAuthWrapper) Public() crypto.PublicKey {
 	cert := ca.signer.GetClientCertificate()
 	leaf, err := x509.ParseCertificate(cert)
 	if err != nil {
-		logging.Warn.Printf("Unable to parse client certificate: %v\n", err)
+		logging.Warnf("Unable to parse client certificate: %v", err)
 		return nil
 	}
 	return leaf.PublicKey

Android/app/src/go/doh/doh.go

@@ -109,7 +109,7 @@ type resolver struct {
 const tcpTimeout time.Duration = 3 * time.Second
 
 func (r *resolver) dial(ctx context.Context, network, addr string) (net.Conn, error) {
-	logging.Debug.Printf("Dialing %s\n", addr)
+	logging.Dbg("DoH(resolver.dial) - dialing", "addr", addr)
 	domain, portStr, err := net.SplitHostPort(addr)
 	if err != nil {
 		return nil, err
@@ -128,23 +128,23 @@ func (r *resolver) dial(ctx context.Context, network, addr string) (net.Conn, er
 	ips := r.ips.Get(domain)
 	confirmed := ips.Confirmed()
 	if confirmed != nil {
-		logging.Debug.Printf("Trying confirmed IP %s for addr %s\n", confirmed.String(), addr)
+		logging.Dbg("DoH(resolver.dial) - trying confirmed IP", "confirmedIP", confirmed, "addr", addr)
 		if conn, err = split.DialWithSplitRetry(ctx, r.dialer, tcpaddr(confirmed), nil); err == nil {
-			logging.Info.Printf("Confirmed IP %s worked\n", confirmed.String())
+			logging.Info("DoH(resolver.dial) - confirmed IP worked", "confirmedIP", confirmed)
 			return conn, nil
 		}
-		logging.Debug.Printf("Confirmed IP %s failed with err %v\n", confirmed.String(), err)
+		logging.Dbg("DoH(resolver.dial) - confirmed IP failed", "confirmedIP", confirmed, "err", err)
 		ips.Disconfirm(confirmed)
 	}
 
-	logging.Debug.Println("Trying all IPs")
+	logging.Dbg("DoH(resolver.dial) - trying all IPs")
 	for _, ip := range ips.GetAll() {
 		if ip.Equal(confirmed) {
 			// Don't try this IP twice.
 			continue
 		}
 		if conn, err = split.DialWithSplitRetry(ctx, r.dialer, tcpaddr(ip), nil); err == nil {
-			logging.Info.Printf("Found working IP: %s\n", ip.String())
+			logging.Info("DoH(resolver.dial) - found working IP", "ip", ip)
 			return conn, nil
 		}
 	}
@@ -328,13 +328,13 @@ func (r *resolver) sendRequest(id uint16, req *http.Request) (response []byte, h
 		if qerr == nil {
 			return
 		}
-		logging.Info.Printf("%d Query failed: %v\n", id, qerr)
+		logging.Info("DoH(resolver.sendRequest) - done", "id", id, "queryError", qerr)
 		if server != nil {
-			logging.Debug.Printf("%d Disconfirming %s\n", id, server.IP.String())
+			logging.Dbg("DoH(resolver.sendRequest) - disconfirming IP", "id", id, "ip", server.IP)
 			r.ips.Get(hostname).Disconfirm(server.IP)
 		}
 		if conn != nil {
-			logging.Info.Printf("%d Closing failing DoH socket\n", id)
+			logging.Info("DoH(resolver.sendRequest) - closing failing DoH socket", "id", id)
 			conn.Close()
 		}
 	}()
@@ -345,10 +345,10 @@ func (r *resolver) sendRequest(id uint16, req *http.Request) (response []byte, h
 	// reading the variables it has set.
 	trace := httptrace.ClientTrace{
 		GetConn: func(hostPort string) {
-			logging.Debug.Printf("%d GetConn(%s)\n", id, hostPort)
+			logging.Dbgf("%d GetConn(%s)", id, hostPort)
 		},
 		GotConn: func(info httptrace.GotConnInfo) {
-			logging.Debug.Printf("%d GotConn(%v)\n", id, info)
+			logging.Dbgf("%d GotConn(%v)", id, info)
 			if info.Conn == nil {
 				return
 			}
@@ -357,41 +357,41 @@ func (r *resolver) sendRequest(id uint16, req *http.Request) (response []byte, h
 			server = conn.RemoteAddr().(*net.TCPAddr)
 		},
 		PutIdleConn: func(err error) {
-			logging.Debug.Printf("%d PutIdleConn(%v)\n", id, err)
+			logging.Dbgf("%d PutIdleConn(%v)", id, err)
 		},
 		GotFirstResponseByte: func() {
-			logging.Debug.Printf("%d GotFirstResponseByte()\n", id)
+			logging.Dbgf("%d GotFirstResponseByte()", id)
 		},
 		Got100Continue: func() {
-			logging.Debug.Printf("%d Got100Continue()\n", id)
+			logging.Dbgf("%d Got100Continue()", id)
 		},
 		Got1xxResponse: func(code int, header textproto.MIMEHeader) error {
-			logging.Debug.Printf("%d Got1xxResponse(%d, %v)\n", id, code, header)
+			logging.Dbgf("%d Got1xxResponse(%d, %v)", id, code, header)
 			return nil
 		},
 		DNSStart: func(info httptrace.DNSStartInfo) {
-			logging.Debug.Printf("%d DNSStart(%v)\n", id, info)
+			logging.Dbgf("%d DNSStart(%v)", id, info)
 		},
 		DNSDone: func(info httptrace.DNSDoneInfo) {
-			logging.Debug.Printf("%d, DNSDone(%v)\n", id, info)
+			logging.Dbgf("%d, DNSDone(%v)", id, info)
 		},
 		ConnectStart: func(network, addr string) {
-			logging.Debug.Printf("%d ConnectStart(%s, %s)\n", id, network, addr)
+			logging.Dbgf("%d ConnectStart(%s, %s)", id, network, addr)
 		},
 		ConnectDone: func(network, addr string, err error) {
-			logging.Debug.Printf("%d ConnectDone(%s, %s, %v)\n", id, network, addr, err)
+			logging.Dbgf("%d ConnectDone(%s, %s, %v)", id, network, addr, err)
 		},
 		TLSHandshakeStart: func() {
-			logging.Debug.Printf("%d TLSHandshakeStart()\n", id)
+			logging.Dbgf("%d TLSHandshakeStart()", id)
 		},
 		TLSHandshakeDone: func(state tls.ConnectionState, err error) {
-			logging.Debug.Printf("%d TLSHandshakeDone(%v, %v)\n", id, state, err)
+			logging.Dbgf("%d TLSHandshakeDone(%v, %v)", id, state, err)
 		},
 		WroteHeaders: func() {
-			logging.Debug.Printf("%d WroteHeaders()\n", id)
+			logging.Dbgf("%d WroteHeaders()", id)
 		},
 		WroteRequest: func(info httptrace.WroteRequestInfo) {
-			logging.Debug.Printf("%d WroteRequest(%v)\n", id, info)
+			logging.Dbgf("%d WroteRequest(%v)", id, info)
 		},
 	}
 	req = req.WithContext(httptrace.WithClientTrace(req.Context(), &trace))
@@ -400,20 +400,20 @@ func (r *resolver) sendRequest(id uint16, req *http.Request) (response []byte, h
 	req.Header.Set("Content-Type", mimetype)
 	req.Header.Set("Accept", mimetype)
 	req.Header.Set("User-Agent", "Intra")
-	logging.Debug.Printf("%d Sending query\n", id)
+	logging.Dbg("DoH(resolver.sendRequest) - sending query", "id", id)
 	httpResponse, err := r.client.Do(req)
 	if err != nil {
 		qerr = &queryError{SendFailed, err}
 		return
 	}
-	logging.Debug.Printf("%d Got response\n", id)
+	logging.Dbg("DoH(resolver.sendRequest) - got response", "id", id)
 	response, err = io.ReadAll(httpResponse.Body)
 	if err != nil {
 		qerr = &queryError{BadResponse, err}
 		return
 	}
 	httpResponse.Body.Close()
-	logging.Debug.Printf("%d Closed response\n", id)
+	logging.Dbg("DoH(resolver.sendRequest) - response closed", "id", id)
 
 	// Update the hostname, which could have changed due to a redirect.
 	hostname = httpResponse.Request.URL.Hostname()
@@ -423,7 +423,7 @@ func (r *resolver) sendRequest(id uint16, req *http.Request) (response []byte, h
 		req.Write(reqBuf)
 		respBuf := new(bytes.Buffer)
 		httpResponse.Write(respBuf)
-		logging.Debug.Printf("%d request: %s\nresponse: %s\n", id, reqBuf.String(), respBuf.String())
+		logging.Dbg("DoH(resolver.sendRequest) - response invalid", "id", id, "req", reqBuf, "resp", respBuf)
 
 		qerr = &queryError{HTTPError, &httpError{httpResponse.StatusCode}}
 		return
@@ -521,7 +521,7 @@ func forwardQuery(r Resolver, q []byte, c io.Writer) error {
 // and close the writer if there was an error.
 func forwardQueryAndCheck(r Resolver, q []byte, c io.WriteCloser) {
 	if err := forwardQuery(r, q, c); err != nil {
-		logging.Warn.Printf("Query forwarding failed: %v\n", err)
+		logging.Warn("DoH(forwardQueryAndCheck) - forwarding failed", "err", err)
 		c.Close()
 	}
 }
@@ -532,26 +532,26 @@ func Accept(r Resolver, c io.ReadWriteCloser) {
 	for {
 		n, err := c.Read(qlbuf)
 		if n == 0 {
-			logging.Debug.Println("TCP query socket clean shutdown")
+			logging.Dbg("DoH(Accept) - TCP query socket clean shutdown")
 			break
 		}
 		if err != nil {
-			logging.Warn.Printf("Error reading from TCP query socket: %v\n", err)
+			logging.Warn("DoH(Accept) - failed to read from TCP query socket", "err", err)
 			break
 		}
 		if n < 2 {
-			logging.Warn.Println("Incomplete query length")
+			logging.Warn("DoH(Accept) - incomplete query length")
 			break
 		}
 		qlen := binary.BigEndian.Uint16(qlbuf)
 		q := make([]byte, qlen)
 		n, err = c.Read(q)
 		if err != nil {
-			logging.Warn.Printf("Error reading query: %v\n", err)
+			logging.Warn("DoH(Accept) - failed to read query", "err", err)
 			break
 		}
 		if n != int(qlen) {
-			logging.Warn.Printf("Incomplete query: %d < %d\n", n, qlen)
+			logging.Warn("DoH(Accept) - incomplete query (n < qlen)", "n", n, "qlen", qlen)
 			break
 		}
 		go forwardQueryAndCheck(r, q, c)
@@ -562,7 +562,7 @@ func Accept(r Resolver, c io.ReadWriteCloser) {
 
 // Servfail returns a SERVFAIL response to the query q.
 func Servfail(q []byte) ([]byte, error) {
-	defer logging.Debug.Println("SERVFAIL response generated")
+	defer logging.Dbg("DoH(SERVFAIL) - response generated")
 	var msg dnsmessage.Message
 	if err := msg.Unpack(q); err != nil {
 		return nil, err
@@ -577,7 +577,7 @@ func Servfail(q []byte) ([]byte, error) {
 func tryServfail(q []byte) []byte {
 	response, err := Servfail(q)
 	if err != nil {
-		logging.Warn.Printf("Error constructing servfail: %v\n", err)
+		logging.Warn("DoH(SERVFAIL) - failed to construct response", "err", err)
 	}
 	return response
 }

Android/app/src/go/doh/ipmap/ipmap.go

@@ -16,11 +16,10 @@ package ipmap
 
 import (
 	"context"
+	"localhost/Intra/Android/app/src/go/logging"
 	"math/rand"
 	"net"
 	"sync"
-
-	"localhost/Intra/Android/app/src/go/logging"
 )
 
 // IPMap maps hostnames to IPSets.
@@ -104,7 +103,7 @@ func (s *IPSet) Add(hostname string) {
 	// Don't hold the ipMap lock during blocking I/O.
 	resolved, err := s.r.LookupIPAddr(context.TODO(), hostname)
 	if err != nil {
-		logging.Warn.Printf("Failed to resolve %s: %v\n", hostname, err)
+		logging.Warnf("Failed to resolve %s: %v", hostname, err)
 	}
 	s.Lock()
 	for _, addr := range resolved {

Android/app/src/go/intra/protect/protect.go

@@ -44,7 +44,7 @@ func makeControl(p Protector) func(string, string, syscall.RawConn) error {
 		return c.Control(func(fd uintptr) {
 			if !p.Protect(int32(fd)) {
 				// TODO: Record and report these errors.
-				logging.Err.Printf("Failed to protect a %s socket\n", network)
+				logging.Errf("Failed to protect a %s socket", network)
 			}
 		})
 	}

Android/app/src/go/intra/sni_reporter.go

@@ -62,11 +62,11 @@ func (r *tcpSNIReporter) Send(report choir.Report) error {
 	r.mu.RUnlock()
 	q, err := choir.FormatQuery(report, suffix)
 	if err != nil {
-		logging.Warn.Printf("Failed to construct query for Choir: %v\n", err)
+		logging.Warnf("Failed to construct query for Choir: %v", err)
 		return nil
 	}
 	if _, err = dns.Query(context.Background(), q); err != nil {
-		logging.Info.Printf("Failed to deliver query for Choir: %v\n", err)
+		logging.Infof("Failed to deliver query for Choir: %v", err)
 	}
 	return nil
 }
@@ -106,13 +106,13 @@ func (r *tcpSNIReporter) Report(summary TCPSocketSummary) {
 	}
 	resultValue, err := choir.NewValue(result)
 	if err != nil {
-		logging.Err.Printf("Bad result %s: %v\n", result, err)
+		logging.Errf("Bad result %s: %v", result, err)
 	}
 	responseValue, err := choir.NewValue(response)
 	if err != nil {
-		logging.Err.Printf("Bad response %s: %v\n", response, err)
+		logging.Errf("Bad response %s: %v", response, err)
 	}
 	if err := reporter.Report(summary.Retry.SNI, resultValue, responseValue); err != nil {
-		logging.Warn.Printf("Choir report failed: %v\n", err)
+		logging.Warnf("Choir report failed: %v", err)
 	}
 }

Android/app/src/go/intra/split/retrier.go

@@ -18,13 +18,12 @@ import (
 	"context"
 	"errors"
 	"io"
+	"localhost/Intra/Android/app/src/go/logging"
 	"math/rand"
 	"net"
 	"sync"
 	"time"
 
-	"localhost/Intra/Android/app/src/go/logging"
-
 	"github.com/Jigsaw-Code/getsni"
 )
 
@@ -121,10 +120,10 @@ const DefaultTimeout time.Duration = 0
 // `addr` is the destination.
 // If `stats` is non-nil, it will be populated with retry-related information.
 func DialWithSplitRetry(ctx context.Context, dialer *net.Dialer, addr *net.TCPAddr, stats *RetryStats) (DuplexConn, error) {
-	logging.Debug.Printf("Split-Retry: dialing to %v...\n", addr)
+	logging.Dbg("SplitRetry(DialWithSplitRetry) - dialing", "addr", addr)
 	before := time.Now()
 	conn, err := dialer.DialContext(ctx, addr.Network(), addr.String())
-	logging.Debug.Printf("Split-Retry: conn dialed, err = %v\n", err)
+	logging.Dbg("SplitRetry(DialWithSplitRetry) - dialed", "err", err)
 	if err != nil {
 		return nil, err
 	}
@@ -167,7 +166,7 @@ func (r *retrier) Read(buf []byte) (n int, err error) {
 			// Read failed.  Retry.
 			n, err = r.retry(buf)
 		}
-		logging.Debug.Println("Split-Retry: direct conn succeeded, no need to split")
+		logging.Dbg("SplitRetry(retrier.Read) - direct conn succeeded, no need to split")
 		close(r.retryCompleteFlag)
 		// Unset read deadline.
 		r.conn.SetReadDeadline(time.Time{})
@@ -178,8 +177,8 @@ func (r *retrier) Read(buf []byte) (n int, err error) {
 }
 
 func (r *retrier) retry(buf []byte) (n int, err error) {
-	logging.Debug.Println("Split-Retry: retrying...")
-	defer func() { logging.Debug.Printf("Split-Retry: retried n = %v, err = %v\n", n, err) }()
+	logging.Dbg("SplitRetry(retrier.retry) - retrying...")
+	defer func() { logging.Dbg("SplitRetry(retrier.retry) - retried", "n", n, "err", err) }()
 
 	r.conn.Close()
 	var newConn net.Conn