Merge pull request cli#13255 from cli/wm/log-no-events

Log when there is no telemetry

Author: williammartin

acceptance/testdata/telemetry/no-telemetry-for-completion.txtar

@@ -4,4 +4,4 @@ env GH_TELEMETRY=log
 env GH_TELEMETRY_SAMPLE_RATE=100
 
 exec gh completion -s bash
-! stderr 'Telemetry payload:'
+stderr 'Telemetry payload: none'

acceptance/testdata/telemetry/no-telemetry-for-extension.txtar

@@ -22,7 +22,7 @@ cd $WORK
 # Run the extension and verify no telemetry is logged
 exec gh hello
 stdout 'hello from extension'
-! stderr 'Telemetry payload:'
+stderr 'Telemetry payload: none'
 
 -- gh-hello.sh --
 #!/usr/bin/env bash

acceptance/testdata/telemetry/no-telemetry-for-ghes-user.txtar

@@ -5,4 +5,4 @@ env GH_TELEMETRY_SAMPLE_RATE=100
 env GH_ENTERPRISE_TOKEN=fake-enterprise-token
 
 exec gh version
-! stderr 'Telemetry payload:'
+stderr 'Telemetry payload: none'

acceptance/testdata/telemetry/no-telemetry-for-send-telemetry.txtar

@@ -8,7 +8,7 @@ env GH_TELEMETRY_ENDPOINT_URL=http://localhost:1
 # It will fail to connect but that's fine — we only care about telemetry logging.
 stdin payload.json
 ! exec gh send-telemetry
-! stderr 'Telemetry payload:'
+stderr 'Telemetry payload: none'
 
 -- payload.json --
 {"events":[{"type":"test","dimensions":{},"measures":{}}]}

internal/ghcmd/cmd.go

@@ -82,19 +82,31 @@ func Main() exitCode {
 	case cfgErr != nil:
 		// Without a valid on-disk config we can't honour user telemetry preferences, so disable it to be safe.
 		telemetryService = &telemetry.NoOpService{}
-	case os.Getenv("GH_PRIVATE_ENABLE_TELEMETRY") == "" || mightBeGHESUser(cfg):
-		telemetryService = &telemetry.NoOpService{}
 	default:
 		telemetryState := telemetry.ParseTelemetryState(cfg.Telemetry().Value)
+		telemetryDisabled := os.Getenv("GH_PRIVATE_ENABLE_TELEMETRY") == "" || mightBeGHESUser(cfg)
+
 		switch telemetryState {
 		case telemetry.Disabled:
 			telemetryService = &telemetry.NoOpService{}
 		case telemetry.Logged:
+			// Always construct the real service in log mode so that the log
+			// flusher runs and surfaces an explicit "Telemetry payload: none"
+			// marker when no events will be sent. This gives the user an
+			// observable signal that telemetry is wired up even when their
+			// context (e.g. GHES) causes events to be dropped.
 			telemetryService = telemetry.NewService(
 				telemetry.LogFlusher(ioStreams.ErrOut, ioStreams.ColorEnabled()),
 				telemetry.WithAdditionalCommonDimensions(additionalCommonDimensions),
 			)
+			if telemetryDisabled {
+				telemetryService.Disable()
+			}
 		case telemetry.Enabled:
+			if telemetryDisabled {
+				telemetryService = &telemetry.NoOpService{}
+				break
+			}
 			sampleRate := 1
 			if v, err := strconv.Atoi(os.Getenv("GH_TELEMETRY_SAMPLE_RATE")); err == nil && v >= 0 && v <= 100 {
 				sampleRate = v

internal/telemetry/telemetry.go

@@ -3,6 +3,7 @@ package telemetry
 
 import (
 	"bytes"
+	"encoding/binary"
 	"encoding/json"
 	"errors"
 	"fmt"
@@ -166,17 +167,24 @@ func WithSampleRate(rate int) telemetryServiceOption {
 }
 
 // LogFlusher returns a flush function that writes telemetry payloads to the provided log writer. This is used for the "log" telemetry mode, which is intended for debugging and development.
+// When there are no events to report (for example the command opted out of telemetry, the user is on GHES, or no events were recorded), a "Telemetry payload: none" marker is written so that the absence of events is observable.
 var LogFlusher = func(log io.Writer, colorEnabled bool) func(payload SendTelemetryPayload) {
 	return func(payload SendTelemetryPayload) {
+		header := "Telemetry payload:"
+		if colorEnabled {
+			header = ansi.Color(header, "cyan+b")
+		}
+
+		if len(payload.Events) == 0 {
+			fmt.Fprintf(log, "%s none\n", header)
+			return
+		}
+
 		payloadBytes, err := json.Marshal(payload)
 		if err != nil {
 			return
 		}
 
-		header := "Telemetry payload:"
-		if colorEnabled {
-			header = ansi.Color(header, "cyan+b")
-		}
 		fmt.Fprintf(log, "%s\n", header)
 
 		if colorEnabled {
@@ -190,8 +198,12 @@ var LogFlusher = func(log io.Writer, colorEnabled bool) func(payload SendTelemet
 }
 
 // GitHubFlusher returns a flush function that sends telemetry payloads to a child `gh send-telemetry` process. This is used for the "enabled" telemetry mode.
+// Empty payloads are dropped without spawning a subprocess.
 var GitHubFlusher = func(executable string) func(payload SendTelemetryPayload) {
 	return func(payload SendTelemetryPayload) {
+		if len(payload.Events) == 0 {
+			return
+		}
 		SpawnSendTelemetry(executable, payload)
 	}
 }
@@ -221,7 +233,7 @@ func NewService(flusher func(SendTelemetryPayload), opts ...telemetryServiceOpti
 	maps.Copy(commonDimensions, telemetryServiceOpts.additionalDimensions)
 
 	hash := uuid.NewSHA1(uuid.Nil, []byte(invocationID))
-	sampleBucket := hash[0] % 100
+	sampleBucket := byte(binary.BigEndian.Uint32(hash[:4]) % 100)
 
 	s := &service{
 		flush:            flusher,
@@ -278,28 +290,29 @@ func (s *service) Flush() {
 	s.mu.Lock()
 	defer s.mu.Unlock()
 
-	if s.disabled {
-		return
-	}
-
 	if s.previouslyCalled {
 		return
 	}
 	s.previouslyCalled = true
 
-	if len(s.events) == 0 {
+	if s.sampleRate > 0 && s.sampleRate < 100 && int(s.sampleBucket) >= s.sampleRate {
 		return
 	}
 
-	if s.sampleRate > 0 && s.sampleRate < 100 && int(s.sampleBucket) >= s.sampleRate {
-		return
+	// When the service has been disabled mid-invocation (e.g. an enterprise host
+	// was contacted), discard any recorded events. We still call the flusher
+	// with an empty payload so that the log-mode flusher can surface the
+	// absence of telemetry rather than leaving the user staring at silence.
+	events := s.events
+	if s.disabled {
+		events = nil
 	}
 
 	payload := SendTelemetryPayload{
-		Events: make([]PayloadEvent, len(s.events)),
+		Events: make([]PayloadEvent, len(events)),
 	}
 
-	for i, recorded := range s.events {
+	for i, recorded := range events {
 		dimensions := map[string]string{
 			"timestamp": recorded.recordedAt.UTC().Format("2006-01-02T15:04:05.000Z"),
 		}

internal/telemetry/telemetry_test.go

@@ -351,6 +351,23 @@ func TestNewServiceLogModeWithColorLogsToWriter(t *testing.T) {
 	assert.Contains(t, output, "\033[", "expected ANSI escape sequences when color is enabled")
 }
 
+func TestLogFlusherWritesNoneMarkerForEmptyPayload(t *testing.T) {
+	t.Run("no color", func(t *testing.T) {
+		var buf bytes.Buffer
+		LogFlusher(&buf, false)(SendTelemetryPayload{})
+		assert.Equal(t, "Telemetry payload: none\n", buf.String())
+	})
+
+	t.Run("with color", func(t *testing.T) {
+		var buf bytes.Buffer
+		LogFlusher(&buf, true)(SendTelemetryPayload{})
+		output := buf.String()
+		assert.Contains(t, output, "Telemetry payload:")
+		assert.Contains(t, output, "none")
+		assert.Contains(t, output, "\x1b") // ANSI escape char for color codes
+	})
+}
+
 func TestServiceDeviceIDFallback(t *testing.T) {
 	t.Cleanup(stubDeviceIDError(errors.New("no device id")))
 
@@ -365,14 +382,19 @@ func TestServiceDeviceIDFallback(t *testing.T) {
 }
 
 func TestServiceFlush(t *testing.T) {
-	t.Run("does nothing when no events recorded", func(t *testing.T) {
+	t.Run("calls flusher with empty payload when no events recorded", func(t *testing.T) {
 		t.Cleanup(stubDeviceID("test-device"))
 
+		var captured SendTelemetryPayload
 		called := false
-		svc := newService(func(SendTelemetryPayload) { called = true }, nil)
+		svc := newService(func(p SendTelemetryPayload) {
+			called = true
+			captured = p
+		}, nil)
 		svc.Flush()
 
-		assert.False(t, called, "flusher should not be called with no events")
+		assert.True(t, called, "flusher should be called even with no events so log mode can surface the absence")
+		assert.Empty(t, captured.Events, "payload should have no events")
 	})
 
 	t.Run("flushes events with merged dimensions", func(t *testing.T) {
@@ -599,45 +621,60 @@ func TestWithAdditionalCommonDimensions(t *testing.T) {
 }
 
 func TestServiceDisable(t *testing.T) {
-	t.Run("prevents flush from sending events", func(t *testing.T) {
+	t.Run("drops recorded events from flushed payload", func(t *testing.T) {
 		t.Cleanup(stubDeviceID("test-device"))
 
+		var captured SendTelemetryPayload
 		called := false
-		svc := newService(func(SendTelemetryPayload) { called = true }, nil)
+		svc := newService(func(p SendTelemetryPayload) {
+			called = true
+			captured = p
+		}, nil)
 
 		svc.Record(ghtelemetry.Event{Type: "test"})
 		svc.Disable()
 		svc.Flush()
 
-		assert.False(t, called, "flusher should not be called after Disable()")
+		assert.True(t, called, "flusher should still be called so log mode can surface the absence of events")
+		assert.Empty(t, captured.Events, "recorded events should be dropped after Disable()")
 	})
 
-	t.Run("prevents flush even with multiple recorded events", func(t *testing.T) {
+	t.Run("drops events even with multiple recorded events", func(t *testing.T) {
 		t.Cleanup(stubDeviceID("test-device"))
 
+		var captured SendTelemetryPayload
 		called := false
-		svc := newService(func(SendTelemetryPayload) { called = true }, nil)
+		svc := newService(func(p SendTelemetryPayload) {
+			called = true
+			captured = p
+		}, nil)
 
 		svc.Record(ghtelemetry.Event{Type: "event1"})
 		svc.Record(ghtelemetry.Event{Type: "event2"})
 		svc.Record(ghtelemetry.Event{Type: "event3"})
 		svc.Disable()
 		svc.Flush()
 
-		assert.False(t, called, "flusher should not be called after Disable()")
+		assert.True(t, called, "flusher should still be called")
+		assert.Empty(t, captured.Events, "recorded events should be dropped after Disable()")
 	})
 
 	t.Run("can be called before any events are recorded", func(t *testing.T) {
 		t.Cleanup(stubDeviceID("test-device"))
 
+		var captured SendTelemetryPayload
 		called := false
-		svc := newService(func(SendTelemetryPayload) { called = true }, nil)
+		svc := newService(func(p SendTelemetryPayload) {
+			called = true
+			captured = p
+		}, nil)
 
 		svc.Disable()
 		svc.Record(ghtelemetry.Event{Type: "test"})
 		svc.Flush()
 
-		assert.False(t, called, "flusher should not be called when disabled before recording")
+		assert.True(t, called, "flusher should still be called")
+		assert.Empty(t, captured.Events, "events recorded after Disable() should be dropped")
 	})
 }