diff --git a/internal/cmd/oohelperd/dns.go b/internal/cmd/oohelperd/dns.go index ce4ef91..0501af4 100644 --- a/internal/cmd/oohelperd/dns.go +++ b/internal/cmd/oohelperd/dns.go @@ -9,6 +9,7 @@ import ( "sync" "time" + "github.com/ooni/probe-cli/v3/internal/measurexlite" "github.com/ooni/probe-cli/v3/internal/model" "github.com/ooni/probe-cli/v3/internal/netxlite" "github.com/ooni/probe-cli/v3/internal/tracex" @@ -26,8 +27,11 @@ type dnsConfig struct { // Domain is the MANDATORY domain to resolve. Domain string + // Logger is the MANDATORY logger to use. + Logger model.Logger + // NewResolver is the MANDATORY factory to create a new resolver. - NewResolver func() model.Resolver + NewResolver func(model.Logger) model.Resolver // Out is the channel where we publish the results. Out chan ctrlDNSResult @@ -42,9 +46,11 @@ func dnsDo(ctx context.Context, config *dnsConfig) { ctx, cancel := context.WithTimeout(ctx, timeout) defer cancel() defer config.Wg.Done() - reso := config.NewResolver() + reso := config.NewResolver(config.Logger) defer reso.CloseIdleConnections() + ol := measurexlite.NewOperationLogger(config.Logger, "DNSLookup %s", config.Domain) addrs, err := reso.LookupHost(ctx, config.Domain) + ol.Stop(err) if addrs == nil { addrs = []string{} // fix: the old test helper did that } diff --git a/internal/cmd/oohelperd/dns_test.go b/internal/cmd/oohelperd/dns_test.go index c925cbe..dfb3b3a 100644 --- a/internal/cmd/oohelperd/dns_test.go +++ b/internal/cmd/oohelperd/dns_test.go @@ -68,7 +68,8 @@ func TestDNSDo(t *testing.T) { ctx := context.Background() config := &dnsConfig{ Domain: "antani.ooni.org", - NewResolver: func() model.Resolver { + Logger: model.DiscardLogger, + NewResolver: func(model.Logger) model.Resolver { return &mocks.Resolver{ MockLookupHost: func(ctx context.Context, domain string) ([]string, error) { return nil, netxlite.ErrOODNSNoSuchHost diff --git a/internal/cmd/oohelperd/handler.go b/internal/cmd/oohelperd/handler.go index f952fe1..c063b76 100644 --- a/internal/cmd/oohelperd/handler.go +++ b/internal/cmd/oohelperd/handler.go @@ -10,6 +10,7 @@ import ( "io" "net/http" + "github.com/ooni/probe-cli/v3/internal/atomicx" "github.com/ooni/probe-cli/v3/internal/model" "github.com/ooni/probe-cli/v3/internal/netxlite" "github.com/ooni/probe-cli/v3/internal/runtimex" @@ -18,20 +19,26 @@ import ( // handler implements the Web Connectivity test helper HTTP API. type handler struct { + // BaseLogger is the MANDATORY logger to use. + BaseLogger model.Logger + + // Indexer is the MANDATORY atomic integer used to assign an index to requests. + Indexer *atomicx.Int64 + // MaxAcceptableBody is the MANDATORY maximum acceptable response body. MaxAcceptableBody int64 // NewClient is the MANDATORY factory to create a new HTTPClient. - NewClient func() model.HTTPClient + NewClient func(model.Logger) model.HTTPClient // NewDialer is the MANDATORY factory to create a new Dialer. - NewDialer func() model.Dialer + NewDialer func(model.Logger) model.Dialer // NewResolver is the MANDATORY factory for creating a new resolver. - NewResolver func() model.Resolver + NewResolver func(model.Logger) model.Resolver // NewTLSHandshaker is the MANDATORY factory for creating a new TLS handshaker. - NewTLSHandshaker func() model.TLSHandshaker + NewTLSHandshaker func(model.Logger) model.TLSHandshaker } var _ http.Handler = &handler{} diff --git a/internal/cmd/oohelperd/handler_test.go b/internal/cmd/oohelperd/handler_test.go index 945de86..08fc37e 100644 --- a/internal/cmd/oohelperd/handler_test.go +++ b/internal/cmd/oohelperd/handler_test.go @@ -10,6 +10,7 @@ import ( "strings" "testing" + "github.com/ooni/probe-cli/v3/internal/atomicx" "github.com/ooni/probe-cli/v3/internal/model" "github.com/ooni/probe-cli/v3/internal/model/mocks" "github.com/ooni/probe-cli/v3/internal/netxlite" @@ -53,17 +54,19 @@ const requestWithoutDomainName = `{ func TestHandlerWorkingAsIntended(t *testing.T) { handler := &handler{ + BaseLogger: model.DiscardLogger, + Indexer: &atomicx.Int64{}, MaxAcceptableBody: 1 << 24, - NewClient: func() model.HTTPClient { + NewClient: func(model.Logger) model.HTTPClient { return http.DefaultClient }, - NewDialer: func() model.Dialer { + NewDialer: func(model.Logger) model.Dialer { return netxlite.NewDialerWithStdlibResolver(model.DiscardLogger) }, - NewResolver: func() model.Resolver { + NewResolver: func(model.Logger) model.Resolver { return netxlite.NewUnwrappedStdlibResolver() }, - NewTLSHandshaker: func() model.TLSHandshaker { + NewTLSHandshaker: func(model.Logger) model.TLSHandshaker { return netxlite.NewTLSHandshakerStdlib(model.DiscardLogger) }, } diff --git a/internal/cmd/oohelperd/http.go b/internal/cmd/oohelperd/http.go index d0444d9..80402f2 100644 --- a/internal/cmd/oohelperd/http.go +++ b/internal/cmd/oohelperd/http.go @@ -30,11 +30,14 @@ type httpConfig struct { // Headers is OPTIONAL and contains the request headers we should set. Headers map[string][]string + // Logger is the MANDATORY logger to use. + Logger model.Logger + // MaxAcceptableBody is MANDATORY and specifies the maximum acceptable body size. MaxAcceptableBody int64 // NewClient is the MANDATORY factory to create a new client. - NewClient func() model.HTTPClient + NewClient func(model.Logger) model.HTTPClient // Out is the MANDATORY channel where we'll post results. Out chan ctrlHTTPResponse @@ -48,6 +51,7 @@ type httpConfig struct { // httpDo performs the HTTP check. func httpDo(ctx context.Context, config *httpConfig) { + ol := measurexlite.NewOperationLogger(config.Logger, "GET %s", config.URL) const timeout = 15 * time.Second ctx, cancel := context.WithTimeout(ctx, timeout) defer cancel() @@ -62,6 +66,7 @@ func httpDo(ctx context.Context, config *httpConfig) { Headers: map[string]string{}, StatusCode: -1, } + ol.Stop(err) return } // The original test helper failed with extra headers while here @@ -74,7 +79,7 @@ func httpDo(ctx context.Context, config *httpConfig) { } } } - clnt := config.NewClient() + clnt := config.NewClient(config.Logger) defer clnt.CloseIdleConnections() resp, err := clnt.Do(req) if err != nil { @@ -86,6 +91,7 @@ func httpDo(ctx context.Context, config *httpConfig) { Headers: map[string]string{}, StatusCode: -1, } + ol.Stop(err) return } defer resp.Body.Close() @@ -95,6 +101,7 @@ func httpDo(ctx context.Context, config *httpConfig) { } reader := &io.LimitedReader{R: resp.Body, N: config.MaxAcceptableBody} data, err := netxlite.ReadAllContext(ctx, reader) + ol.Stop(err) config.Out <- ctrlHTTPResponse{ BodyLength: int64(len(data)), Failure: httpMapFailure(err), diff --git a/internal/cmd/oohelperd/http_test.go b/internal/cmd/oohelperd/http_test.go index 8821a8e..3328be3 100644 --- a/internal/cmd/oohelperd/http_test.go +++ b/internal/cmd/oohelperd/http_test.go @@ -20,8 +20,9 @@ func TestHTTPDoWithInvalidURL(t *testing.T) { wg.Add(1) go httpDo(ctx, &httpConfig{ Headers: nil, + Logger: model.DiscardLogger, MaxAcceptableBody: 1 << 24, - NewClient: func() model.HTTPClient { + NewClient: func(model.Logger) model.HTTPClient { return http.DefaultClient }, Out: httpch, @@ -44,8 +45,9 @@ func TestHTTPDoWithHTTPTransportFailure(t *testing.T) { wg.Add(1) go httpDo(ctx, &httpConfig{ Headers: nil, + Logger: model.DiscardLogger, MaxAcceptableBody: 1 << 24, - NewClient: func() model.HTTPClient { + NewClient: func(model.Logger) model.HTTPClient { return &http.Client{ Transport: &mocks.HTTPTransport{ MockRoundTrip: func(req *http.Request) (*http.Response, error) { diff --git a/internal/cmd/oohelperd/logging.go b/internal/cmd/oohelperd/logging.go new file mode 100644 index 0000000..207a9a4 --- /dev/null +++ b/internal/cmd/oohelperd/logging.go @@ -0,0 +1,41 @@ +package main + +import "github.com/ooni/probe-cli/v3/internal/model" + +// indexLogger is a logger with an index. +type indexLogger struct { + indexstr string + logger model.Logger +} + +var _ model.Logger = &indexLogger{} + +// Debug implements DebugLogger.Debug +func (p *indexLogger) Debug(msg string) { + p.logger.Debug(p.indexstr + msg) +} + +// Debugf implements DebugLogger.Debugf +func (p *indexLogger) Debugf(format string, v ...interface{}) { + p.logger.Debugf(p.indexstr+format, v...) +} + +// Info implements InfoLogger.Info +func (p *indexLogger) Info(msg string) { + p.logger.Info(p.indexstr + msg) +} + +// Infov implements InfoLogger.Infov +func (p *indexLogger) Infof(format string, v ...interface{}) { + p.logger.Infof(p.indexstr+format, v...) +} + +// Warn implements Logger.Warn +func (p *indexLogger) Warn(msg string) { + p.logger.Warn(p.indexstr + msg) +} + +// Warnf implements Logger.Warnf +func (p *indexLogger) Warnf(format string, v ...interface{}) { + p.logger.Warnf(p.indexstr+format, v...) +} diff --git a/internal/cmd/oohelperd/logging_test.go b/internal/cmd/oohelperd/logging_test.go new file mode 100644 index 0000000..169d07e --- /dev/null +++ b/internal/cmd/oohelperd/logging_test.go @@ -0,0 +1,105 @@ +package main + +import ( + "testing" + + "github.com/ooni/probe-cli/v3/internal/model/mocks" +) + +func TestIndexLogger(t *testing.T) { + t.Run("Debug", func(t *testing.T) { + expected := "<0>antani" + base := &mocks.Logger{ + MockDebug: func(message string) { + if message != expected { + t.Fatal("unexpected message") + } + }, + } + logger := &indexLogger{ + indexstr: "<0>", + logger: base, + } + logger.Debug("antani") + }) + + t.Run("Info", func(t *testing.T) { + expected := "<0>antani" + base := &mocks.Logger{ + MockInfo: func(message string) { + if message != expected { + t.Fatal("unexpected message") + } + }, + } + logger := &indexLogger{ + indexstr: "<0>", + logger: base, + } + logger.Info("antani") + }) + + t.Run("Warn", func(t *testing.T) { + expected := "<0>antani" + base := &mocks.Logger{ + MockWarn: func(message string) { + if message != expected { + t.Fatal("unexpected message") + } + }, + } + logger := &indexLogger{ + indexstr: "<0>", + logger: base, + } + logger.Warn("antani") + }) + + t.Run("Debugf", func(t *testing.T) { + expected := "<0>antani%d" + base := &mocks.Logger{ + MockDebugf: func(format string, v ...any) { + if format != expected { + t.Fatal("unexpected message") + } + }, + } + logger := &indexLogger{ + indexstr: "<0>", + logger: base, + } + logger.Debugf("antani%d", 11) + }) + + t.Run("Infof", func(t *testing.T) { + expected := "<0>antani%d" + base := &mocks.Logger{ + MockInfof: func(format string, v ...any) { + if format != expected { + t.Fatal("unexpected message") + } + }, + } + logger := &indexLogger{ + indexstr: "<0>", + logger: base, + } + logger.Infof("antani%d", 11) + }) + + t.Run("Warnf", func(t *testing.T) { + expected := "<0>antani%d" + base := &mocks.Logger{ + MockWarnf: func(format string, v ...any) { + if format != expected { + t.Fatal("unexpected message") + } + }, + } + logger := &indexLogger{ + indexstr: "<0>", + logger: base, + } + logger.Warnf("antani%d", 11) + }) +} diff --git a/internal/cmd/oohelperd/main.go b/internal/cmd/oohelperd/main.go index b7904d0..b583dd0 100644 --- a/internal/cmd/oohelperd/main.go +++ b/internal/cmd/oohelperd/main.go @@ -10,6 +10,7 @@ import ( "time" "github.com/apex/log" + "github.com/ooni/probe-cli/v3/internal/atomicx" "github.com/ooni/probe-cli/v3/internal/model" "github.com/ooni/probe-cli/v3/internal/netxlite" "github.com/ooni/probe-cli/v3/internal/runtimex" @@ -29,11 +30,11 @@ func init() { srvCtx, srvCancel = context.WithCancel(context.Background()) } -func newResolver() model.Resolver { +func newResolver(logger model.Logger) model.Resolver { // Implementation note: pin to a specific resolver so we don't depend upon the // default resolver configured by the box. Also, use an encrypted transport thus // we're less vulnerable to any policy implemented by the box's provider. - resolver := netxlite.NewParallelDNSOverHTTPSResolver(log.Log, "https://8.8.8.8/dns-query") + resolver := netxlite.NewParallelDNSOverHTTPSResolver(logger, "https://dns.google/dns-query") return resolver } @@ -54,16 +55,18 @@ func main() { defer srvCancel() mux := http.NewServeMux() mux.Handle("/", &handler{ + BaseLogger: log.Log, + Indexer: &atomicx.Int64{}, MaxAcceptableBody: maxAcceptableBody, - NewClient: func() model.HTTPClient { - return netxlite.NewHTTPClientWithResolver(log.Log, newResolver()) + NewClient: func(logger model.Logger) model.HTTPClient { + return netxlite.NewHTTPClientWithResolver(logger, newResolver(logger)) }, - NewDialer: func() model.Dialer { - return netxlite.NewDialerWithResolver(log.Log, newResolver()) + NewDialer: func(logger model.Logger) model.Dialer { + return netxlite.NewDialerWithResolver(logger, newResolver(logger)) }, NewResolver: newResolver, - NewTLSHandshaker: func() model.TLSHandshaker { - return netxlite.NewTLSHandshakerStdlib(log.Log) + NewTLSHandshaker: func(logger model.Logger) model.TLSHandshaker { + return netxlite.NewTLSHandshakerStdlib(logger) }, }) srv := &http.Server{Addr: *endpoint, Handler: mux} diff --git a/internal/cmd/oohelperd/measure.go b/internal/cmd/oohelperd/measure.go index e11a043..0d57651 100644 --- a/internal/cmd/oohelperd/measure.go +++ b/internal/cmd/oohelperd/measure.go @@ -6,6 +6,7 @@ package main import ( "context" + "fmt" "net" "net/url" "sync" @@ -24,9 +25,16 @@ type ( // measure performs the measurement described by the request and // returns the corresponding response or an error. func measure(ctx context.Context, config *handler, creq *ctrlRequest) (*ctrlResponse, error) { + // create indexed logger + logger := &indexLogger{ + indexstr: fmt.Sprintf("<#%d> ", config.Indexer.Add(1)), + logger: config.BaseLogger, + } + // parse input for correctness URL, err := url.Parse(creq.HTTPRequest) if err != nil { + logger.Warnf("cannot parse URL: %s", err.Error()) return nil, err } wg := &sync.WaitGroup{} @@ -37,6 +45,7 @@ func measure(ctx context.Context, config *handler, creq *ctrlRequest) (*ctrlResp wg.Add(1) go dnsDo(ctx, &dnsConfig{ Domain: URL.Hostname(), + Logger: logger, NewResolver: config.NewResolver, Out: dnsch, Wg: wg, @@ -78,6 +87,7 @@ func measure(ctx context.Context, config *handler, creq *ctrlRequest) (*ctrlResp Address: endpoint.Addr, EnableTLS: endpoint.TLS, Endpoint: endpoint.Epnt, + Logger: logger, NewDialer: config.NewDialer, NewTSLHandshaker: config.NewTLSHandshaker, URLHostname: URL.Hostname(), @@ -91,6 +101,7 @@ func measure(ctx context.Context, config *handler, creq *ctrlRequest) (*ctrlResp wg.Add(1) go httpDo(ctx, &httpConfig{ Headers: creq.HTTPRequestHeaders, + Logger: logger, MaxAcceptableBody: config.MaxAcceptableBody, NewClient: config.NewClient, Out: httpch, diff --git a/internal/cmd/oohelperd/tcpconnect.go b/internal/cmd/oohelperd/tcpconnect.go index bd71942..1db8814 100644 --- a/internal/cmd/oohelperd/tcpconnect.go +++ b/internal/cmd/oohelperd/tcpconnect.go @@ -47,11 +47,14 @@ type tcpConfig struct { // Endpoint is the MANDATORY endpoint to connect to. Endpoint string + // Logger is the MANDATORY logger to use. + Logger model.Logger + // NewDialer is the MANDATORY factory for creating a new dialer. - NewDialer func() model.Dialer + NewDialer func(model.Logger) model.Dialer // NewTSLHandshaker is the MANDATORY factory for creating a new handshaker. - NewTSLHandshaker func() model.TLSHandshaker + NewTSLHandshaker func(model.Logger) model.TLSHandshaker // Out is the MANDATORY where we'll post the TCP measurement results. Out chan *tcpResultPair @@ -78,13 +81,21 @@ func tcpDo(ctx context.Context, config *tcpConfig) { defer func() { config.Out <- out }() - dialer := config.NewDialer() + ol := measurexlite.NewOperationLogger( + config.Logger, + "TCPConnect %s EnableTLS=%v SNI=%s", + config.Endpoint, + config.EnableTLS, + config.URLHostname, + ) + dialer := config.NewDialer(config.Logger) defer dialer.CloseIdleConnections() conn, err := dialer.DialContext(ctx, "tcp", config.Endpoint) out.TCP.Failure = tcpMapFailure(newfailure(err)) out.TCP.Status = err == nil defer measurexlite.MaybeClose(conn) if err != nil || !config.EnableTLS { + ol.Stop(err) return } tlsConfig := &tls.Config{ @@ -92,8 +103,9 @@ func tcpDo(ctx context.Context, config *tcpConfig) { RootCAs: netxlite.NewDefaultCertPool(), ServerName: config.URLHostname, } - thx := config.NewTSLHandshaker() + thx := config.NewTSLHandshaker(config.Logger) tlsConn, _, err := thx.Handshake(ctx, conn, tlsConfig) + ol.Stop(err) out.TLS = &ctrlTLSResult{ ServerName: config.URLHostname, Status: err == nil,