ooni-probe-cli/internal/engine/legacy/netxlogger/netxlogger.go

// Package netxlogger is a logger for netx events.
//
// This package is a fork of github.com/ooni/netx/x/logger where
// we applied ooni/probe-engine specific customisations.
package netxlogger

import (
	"net/http"
	"strings"

	"github.com/ooni/probe-cli/v3/internal/engine/internal/tlsx"
	"github.com/ooni/probe-cli/v3/internal/engine/legacy/netx/modelx"
)

// Logger is the interface we expect from a logger
type Logger interface {
	Debug(msg string)
	Debugf(format string, v ...interface{})
}

// Handler is a handler that logs events.
type Handler struct {
	logger Logger
}

// NewHandler returns a new logging handler.
func NewHandler(logger Logger) *Handler {
	return &Handler{logger: logger}
}

// OnMeasurement logs the specific measurement
func (h *Handler) OnMeasurement(m modelx.Measurement) {
	// DNS
	if m.ResolveStart != nil {
		h.logger.Debugf(
			"[httpTxID: %d] resolving: %s",
			m.ResolveStart.TransactionID,
			m.ResolveStart.Hostname,
		)
	}
	if m.ResolveDone != nil {
		h.logger.Debugf(
			"[httpTxID: %d] resolve done: %s, %s",
			m.ResolveDone.TransactionID,
			fmtError(m.ResolveDone.Error),
			m.ResolveDone.Addresses,
		)
	}

	// Syscalls
	if m.Connect != nil {
		h.logger.Debugf(
			"[httpTxID: %d] connect done: %s, %s (rtt=%s)",
			m.Connect.TransactionID,
			fmtError(m.Connect.Error),
			m.Connect.RemoteAddress,
			m.Connect.SyscallDuration,
		)
	}

	// TLS
	if m.TLSHandshakeStart != nil {
		h.logger.Debugf(
			"[httpTxID: %d] TLS handshake: (forceSNI='%s')",
			m.TLSHandshakeStart.TransactionID,
			m.TLSHandshakeStart.SNI,
		)
	}
	if m.TLSHandshakeDone != nil {
		h.logger.Debugf(
			"[httpTxID: %d] TLS done: %s, %s (alpn='%s')",
			m.TLSHandshakeDone.TransactionID,
			fmtError(m.TLSHandshakeDone.Error),
			tlsx.VersionString(m.TLSHandshakeDone.ConnectionState.Version),
			m.TLSHandshakeDone.ConnectionState.NegotiatedProtocol,
		)
	}

	// HTTP round trip
	if m.HTTPRequestHeadersDone != nil {
		proto := "HTTP/1.1"
		for key := range m.HTTPRequestHeadersDone.Headers {
			if strings.HasPrefix(key, ":") {
				proto = "HTTP/2.0"
				break
			}
		}
		h.logger.Debugf(
			"[httpTxID: %d] > %s %s %s",
			m.HTTPRequestHeadersDone.TransactionID,
			m.HTTPRequestHeadersDone.Method,
			m.HTTPRequestHeadersDone.URL.RequestURI(),
			proto,
		)
		if proto == "HTTP/2.0" {
			h.logger.Debugf(
				"[httpTxID: %d] > Host: %s",
				m.HTTPRequestHeadersDone.TransactionID,
				m.HTTPRequestHeadersDone.URL.Host,
			)
		}
		for key, values := range m.HTTPRequestHeadersDone.Headers {
			if strings.HasPrefix(key, ":") {
				continue
			}
			for _, value := range values {
				h.logger.Debugf(
					"[httpTxID: %d] > %s: %s",
					m.HTTPRequestHeadersDone.TransactionID,
					key, value,
				)
			}
		}
		h.logger.Debugf(
			"[httpTxID: %d] >", m.HTTPRequestHeadersDone.TransactionID)
	}
	if m.HTTPRequestDone != nil {
		h.logger.Debugf(
			"[httpTxID: %d] request sent; waiting for response",
			m.HTTPRequestDone.TransactionID,
		)
	}
	if m.HTTPResponseStart != nil {
		h.logger.Debugf(
			"[httpTxID: %d] start receiving response",
			m.HTTPResponseStart.TransactionID,
		)
	}
	if m.HTTPRoundTripDone != nil && m.HTTPRoundTripDone.Error == nil {
		h.logger.Debugf(
			"[httpTxID: %d] < %s %d %s",
			m.HTTPRoundTripDone.TransactionID,
			m.HTTPRoundTripDone.ResponseProto,
			m.HTTPRoundTripDone.ResponseStatusCode,
			http.StatusText(int(m.HTTPRoundTripDone.ResponseStatusCode)),
		)
		for key, values := range m.HTTPRoundTripDone.ResponseHeaders {
			for _, value := range values {
				h.logger.Debugf(
					"[httpTxID: %d] < %s: %s",
					m.HTTPRoundTripDone.TransactionID,
					key, value,
				)
			}
		}
		h.logger.Debugf(
			"[httpTxID: %d] <", m.HTTPRoundTripDone.TransactionID)
	}

	// HTTP response body
	if m.HTTPResponseBodyPart != nil {
		h.logger.Debugf(
			"[httpTxID: %d] body part: %s, %d",
			m.HTTPResponseBodyPart.TransactionID,
			fmtError(m.HTTPResponseBodyPart.Error),
			len(m.HTTPResponseBodyPart.Data),
		)
	}
	if m.HTTPResponseDone != nil {
		h.logger.Debugf(
			"[httpTxID: %d] end of response",
			m.HTTPResponseDone.TransactionID,
		)
	}
}

func fmtError(err error) (s string) {
	s = "success"
	if err != nil {
		s = err.Error()
	}
	return
}