egress: log donor country not IP, make deploys verifiable, bump to v2.3.14

common/version.go

@@ -1,4 +1,4 @@
 package common
 
 // Must be a valid semver
-const Version = "v2.3.13"
+const Version = "v2.3.14"

egress/egresslib_test.go

@@ -1,11 +1,16 @@
 package egress
 
 import (
+	"bytes"
 	"context"
 	"crypto/tls"
+	"log/slog"
 	"net"
+	"strings"
 	"testing"
 	"time"
+
+	"github.com/getlantern/broflake/common"
 )
 
 // TestNewListener_CleanShutdownDoesNotPanic is a regression test for the
@@ -53,3 +58,44 @@ func TestNewListener_CleanShutdownDoesNotPanic(t *testing.T) {
 	// machine and doesn't meaningfully slow down the test suite.
 	time.Sleep(100 * time.Millisecond)
 }
+
+// The startup version line is the only thing that says which build is running:
+// the spans carry no service.version, so before this the answer lived on the
+// host. Asserted through the real initMetrics path — the metrics tests stub
+// initMetricsFn and the OTLP tests call enableOTELLogs directly, so neither
+// would notice this line disappearing.
+func TestNewListener_LogsTheRunningVersion(t *testing.T) {
+	// No collector configured, so enableOTELLogs no-ops and this exercises the
+	// version line alone rather than standing up an exporter.
+	t.Setenv("OTEL_EXPORTER_OTLP_ENDPOINT", "")
+	t.Setenv("OTEL_EXPORTER_OTLP_LOGS_ENDPOINT", "")
+
+	var buf bytes.Buffer
+	prev := slog.Default()
+	slog.SetDefault(slog.New(slog.NewTextHandler(&buf, &slog.HandlerOptions{Level: slog.LevelDebug})))
+	t.Cleanup(func() { slog.SetDefault(prev) })
+
+	tcpL, err := net.Listen("tcp", "127.0.0.1:0")
+	if err != nil {
+		t.Fatalf("listen: %v", err)
+	}
+	t.Cleanup(func() { _ = tcpL.Close() })
+
+	ll, err := NewListener(context.Background(), tcpL, &tls.Config{
+		NextProtos:         []string{"broflake"},
+		InsecureSkipVerify: true,
+	})
+	if err != nil {
+		t.Fatalf("NewListener: %v", err)
+	}
+	t.Cleanup(func() { _ = ll.Close() })
+
+	out := buf.String()
+	if !strings.Contains(out, "Egress telemetry initialized") {
+		t.Fatalf("no startup line naming the build: %q", out)
+	}
+	if !strings.Contains(out, common.Version) {
+		t.Errorf("the startup line does not carry %s, so a deploy stays unverifiable: %q",
+			common.Version, out)
+	}
+}

egress/metrics.go

@@ -3,13 +3,16 @@ package egress
 import (
 	"context"
 	"errors"
+	"log/slog"
 	"sync"
 	"sync/atomic"
 
 	"github.com/getlantern/telemetry"
 	"go.opentelemetry.io/otel"
 	"go.opentelemetry.io/otel/attribute"
 	"go.opentelemetry.io/otel/metric"
+
+	"github.com/getlantern/broflake/common"
 )
 
 // OTel setup for the egress, scoped to the process rather than to a listener.
@@ -196,6 +199,15 @@ func initMetrics(ctx context.Context) (func(context.Context) error, error) {
 		return nil, shutdownAfter(ctx, shutdown, err)
 	}
 
+	// Last, so it cannot announce success for setup that then fails — every
+	// step above returns through shutdownAfter. Still after enableOTELLogs, so
+	// the handler is installed and this is exported rather than only written to
+	// stderr. Nothing else says which build is running: the spans carry no
+	// service.version, so until now the only way to know what was deployed was
+	// to ask the host, which is how a stale binary went unnoticed for days
+	// while newer releases were assumed live.
+	slog.Info("Egress telemetry initialized", "egress_version", common.Version)
+
 	return shutdown, nil
 }
 

egress/otellogs.go

@@ -3,7 +3,9 @@ package egress
 import (
 	"context"
 	"log/slog"
+	"net/url"
 	"os"
+	"strings"
 	"time"
 
 	"go.opentelemetry.io/contrib/bridges/otelslog"
@@ -53,13 +55,26 @@ func enableOTELLogs(ctx context.Context) func(context.Context) error {
 	// Same shape as telemetry.EnableOTELTracing returning a no-op when its
 	// sampler variables are absent: absent configuration means the feature is
 	// off, not misconfigured.
-	if !otlpLogsConfigured() {
+	endpointVar, endpoint := otlpLogsEndpoint()
+	if endpointVar == "" {
+		// Warn rather than returning quietly. Whether export is on is not
+		// otherwise observable: the answer lives in the absence of logs in the
+		// collector, which is indistinguishable from a healthy egress that
+		// simply had nothing to say. Someone deploying this needs to be able
+		// to confirm it from the journal.
+		slog.Warn("Log export disabled: no OTLP logs endpoint configured",
+			"checked", strings.Join(otlpLogsEndpointVars, ", "))
 		return func(context.Context) error { return nil }
 	}
 
 	exp, err := otlploghttp.New(ctx)
 	if err != nil {
-		slog.Warn("Log export disabled; could not build the OTLP log exporter", "err", err)
+		// The exporter reports what it could not parse, which for an endpoint
+		// problem is the endpoint — credentials included. Substituted rather
+		// than dropped, so the diagnostic survives without the secret.
+		slog.Warn("Log export disabled; could not build the OTLP log exporter",
+			"err", strings.ReplaceAll(err.Error(), endpoint, redactEndpoint(endpoint)),
+			"endpoint", redactEndpoint(endpoint), "from", endpointVar)
 		return func(context.Context) error { return nil }
 	}
 
@@ -81,6 +96,14 @@ func enableOTELLogs(ctx context.Context) func(context.Context) error {
 	// Wrap whatever the binary installed rather than replacing it — each
 	// egress/cmd main sets a stderr TextHandler at Debug, and that is still
 	// the only place the high-volume lines are readable.
+	// Emitted before the handler swap so this line is stderr-only, never queued
+	// for export. It is the line an operator reads to find out whether export
+	// works, so routing it through the exporter it describes would be circular.
+	// (stderr would receive it either way — the tee's local leg is stderr — so
+	// the ordering is about not exporting it, not about reaching the journal.)
+	slog.Info("Log export enabled",
+		"endpoint", redactEndpoint(endpoint), "from", endpointVar, "min_level", otelLogLevel)
+
 	local := slog.Default().Handler()
 	remote := otelslog.NewHandler("github.com/getlantern/broflake/egress",
 		otelslog.WithLoggerProvider(lp))
@@ -106,19 +129,27 @@ func enableOTELLogs(ctx context.Context) func(context.Context) error {
 // hold up process exit.
 const logShutdownTimeout = 5 * time.Second
 
-// otlpLogsConfigured reports whether an OTLP endpoint is configured for logs.
-// Checks the signal-specific variable first, matching OTEL's own precedence,
-// then the shared one.
-func otlpLogsConfigured() bool {
-	for _, k := range []string{
-		"OTEL_EXPORTER_OTLP_LOGS_ENDPOINT",
-		"OTEL_EXPORTER_OTLP_ENDPOINT",
-	} {
-		if os.Getenv(k) != "" {
-			return true
+// otlpLogsEndpointVars are the variables that can supply a logs endpoint, in
+// OTEL's own precedence order: signal-specific first, then shared.
+//
+// Deliberately not the metrics or traces variables. A host that sets only
+// OTEL_EXPORTER_OTLP_METRICS_ENDPOINT has a collector, but says nothing about
+// where logs should go — otlploghttp would fall back to localhost:4318 and
+// queue records for something that is not there.
+var otlpLogsEndpointVars = []string{
+	"OTEL_EXPORTER_OTLP_LOGS_ENDPOINT",
+	"OTEL_EXPORTER_OTLP_ENDPOINT",
+}
+
+// otlpLogsEndpoint returns the variable that supplied a logs endpoint and its
+// value, or two empty strings when none is configured.
+func otlpLogsEndpoint() (name, value string) {
+	for _, k := range otlpLogsEndpointVars {
+		if v := os.Getenv(k); v != "" {
+			return k, v
 		}
 	}
-	return false
+	return "", ""
 }
 
 // teeHandler writes each record to both destinations. Not a general-purpose
@@ -144,8 +175,8 @@ func (h *teeHandler) Handle(ctx context.Context, r slog.Record) error {
 		firstErr = h.local.Handle(ctx, r)
 	}
 	if h.remoteEnabled(ctx, r.Level) {
-		// Clone because a Handler is allowed to retain or mutate the record's
-		// attrs, and the local handler has already been handed this one.
+		// Clone because a Handler may retain or mutate the record it is given,
+		// and the local leg has already been handed this one.
 		if err := h.remote.Handle(ctx, r.Clone()); err != nil && firstErr == nil {
 			firstErr = err
 		}
@@ -160,3 +191,28 @@ func (h *teeHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
 func (h *teeHandler) WithGroup(name string) slog.Handler {
 	return &teeHandler{local: h.local.WithGroup(name), remote: h.remote.WithGroup(name)}
 }
+
+// redactEndpoint strips anything an OTLP endpoint could legally carry as a
+// credential before it reaches a log. These URLs are configuration rather than
+// user input, but "https://user:token@collector/v1/logs" and
+// "https://collector/v1/logs?api-key=..." are both valid values, and the journal
+// is read by more people than the config is. Scheme, host and path are what make
+// the line useful.
+//
+// Anything without a host is refused outright rather than returned. url.Parse
+// accepts opaque and hostless strings — "secret", "http:token" — without error,
+// and clearing User does nothing to those, so returning the parsed form would
+// echo the whole value. Same rule as sanitizeReportURL: with no structure to
+// rely on, there is no way to tell which part was secret.
+func redactEndpoint(raw string) string {
+	u, err := url.Parse(raw)
+	if err != nil || u.Host == "" {
+		return "(unparseable)"
+	}
+	u.User = nil
+	u.RawQuery = ""
+	u.ForceQuery = false
+	u.Fragment = ""
+	u.RawFragment = ""
+	return u.String()
+}