diff --git a/internal/engine/allexperiments.go b/internal/engine/allexperiments.go index 8e31b6d..20a7c34 100644 --- a/internal/engine/allexperiments.go +++ b/internal/engine/allexperiments.go @@ -27,6 +27,7 @@ import ( "github.com/ooni/probe-cli/v3/internal/engine/experiment/tor" "github.com/ooni/probe-cli/v3/internal/engine/experiment/torsf" "github.com/ooni/probe-cli/v3/internal/engine/experiment/urlgetter" + "github.com/ooni/probe-cli/v3/internal/engine/experiment/vanillator" "github.com/ooni/probe-cli/v3/internal/engine/experiment/webconnectivity" "github.com/ooni/probe-cli/v3/internal/engine/experiment/webstepsx" "github.com/ooni/probe-cli/v3/internal/engine/experiment/whatsapp" @@ -327,6 +328,18 @@ var experimentsByName = map[string]func(*Session) *ExperimentBuilder{ } }, + "vanilla_tor": func(session *Session) *ExperimentBuilder { + return &ExperimentBuilder{ + build: func(config interface{}) *Experiment { + return NewExperiment(session, vanillator.NewExperimentMeasurer( + *config.(*vanillator.Config), + )) + }, + config: &vanillator.Config{}, + inputPolicy: InputNone, + } + }, + "web_connectivity": func(session *Session) *ExperimentBuilder { return &ExperimentBuilder{ build: func(config interface{}) *Experiment { diff --git a/internal/engine/experiment/torsf/testdata/partial.log b/internal/engine/experiment/torsf/testdata/partial.log new file mode 100644 index 0000000..37612c2 --- /dev/null +++ b/internal/engine/experiment/torsf/testdata/partial.log @@ -0,0 +1,27 @@ +Feb 04 15:04:29.000 [notice] Tor 0.4.6.9 opening new log file. +Feb 04 15:04:29.360 [notice] We compiled with OpenSSL 101010cf: OpenSSL 1.1.1l FIPS 24 Aug 2021 and we are running with OpenSSL 101010cf: 1.1.1l. These two versions should be binary compatible. +Feb 04 15:04:29.363 [notice] Tor 0.4.6.9 running on Linux with Libevent 2.1.12-stable, OpenSSL 1.1.1l, Zlib 1.2.11, Liblzma 5.2.5, Libzstd 1.5.2 and Glibc 2.34 as libc. +Feb 04 15:04:29.363 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning +Feb 04 15:04:29.363 [warn] Tor was compiled with zstd 1.5.1, but is running with zstd 1.5.2. For safety, we'll avoid using advanced zstd functionality. +Feb 04 15:04:29.363 [notice] Read configuration file "/home/sbs/.miniooni/tunnel/torsf/tor/torrc-2981077975". +Feb 04 15:04:29.366 [notice] Opening Control listener on 127.0.0.1:0 +Feb 04 15:04:29.367 [notice] Control listener listening on port 41423. +Feb 04 15:04:29.367 [notice] Opened Control listener connection (ready) on 127.0.0.1:41423 +Feb 04 15:04:29.367 [notice] DisableNetwork is set. Tor will not make or accept non-control network connections. Shutting down all existing connections. +Feb 04 15:04:29.000 [notice] Parsing GEOIP IPv4 file /usr/share/tor/geoip. +Feb 04 15:04:29.000 [notice] Parsing GEOIP IPv6 file /usr/share/tor/geoip6. +Feb 04 15:04:29.000 [notice] Bootstrapped 0% (starting): Starting +Feb 04 15:04:29.000 [notice] Starting with guard context "bridges" +Feb 04 15:04:29.000 [notice] new bridge descriptor 'flakey4' (cached): $2B280B23E1107BB62ABFC40DDCC8824814F80A72~flakey4 [1zOHpg+FxqQfi/6jDLtCpHHqBTH8gjYmCKXkus1D5Ko] at 192.0.2.3 +Feb 04 15:04:29.000 [notice] Delaying directory fetches: DisableNetwork is set. +Feb 04 15:04:29.000 [notice] New control connection opened from 127.0.0.1. +Feb 04 15:04:29.000 [notice] Opening Socks listener on 127.0.0.1:0 +Feb 04 15:04:29.000 [notice] Socks listener listening on port 42089. +Feb 04 15:04:29.000 [notice] Opened Socks listener connection (ready) on 127.0.0.1:42089 +Feb 04 15:04:29.000 [notice] Tor 0.4.6.9 opening log file. +Feb 04 15:04:29.000 [notice] Bootstrapped 1% (conn_pt): Connecting to pluggable transport +Feb 04 15:04:30.000 [notice] Bootstrapped 2% (conn_done_pt): Connected to pluggable transport +Feb 04 15:04:30.000 [notice] Bootstrapped 10% (conn_done): Connected to a relay +Feb 04 15:06:20.000 [notice] Bootstrapped 14% (handshake): Handshaking with a relay +Feb 04 15:06:24.000 [notice] Bootstrapped 15% (handshake_done): Handshake with a relay done +Feb 04 15:06:39.000 [notice] Catching signal TERM, exiting cleanly. diff --git a/internal/engine/experiment/torsf/torsf.go b/internal/engine/experiment/torsf/torsf.go index f964b44..d46307e 100644 --- a/internal/engine/experiment/torsf/torsf.go +++ b/internal/engine/experiment/torsf/torsf.go @@ -1,29 +1,31 @@ -// Package torsf contains the torsf experiment. This experiment -// measures the bootstrapping of tor using snowflake. +// Package torsf contains the torsf experiment. // // See https://github.com/ooni/spec/blob/master/nettests/ts-030-torsf.md package torsf import ( - "bytes" "context" "errors" "fmt" - "os" "path" - "regexp" "time" - "github.com/apex/log" "github.com/ooni/probe-cli/v3/internal/bytecounter" "github.com/ooni/probe-cli/v3/internal/engine/netx/archival" "github.com/ooni/probe-cli/v3/internal/model" "github.com/ooni/probe-cli/v3/internal/ptx" + "github.com/ooni/probe-cli/v3/internal/runtimex" + "github.com/ooni/probe-cli/v3/internal/torlogs" "github.com/ooni/probe-cli/v3/internal/tunnel" ) -// testVersion is the tor experiment version. -const testVersion = "0.2.0" +// Implementation note: this file is written with easy diffing with respect +// to internal/engine/experiment/vanillator/vanillator.go in mind. +// +// We may want to have a single implementation for both nettests in the future. + +// testVersion is the experiment version. +const testVersion = "0.3.0" // Config contains the experiment config. type Config struct { @@ -42,23 +44,44 @@ type TestKeys struct { // BootstrapTime contains the bootstrap time on success. BootstrapTime float64 `json:"bootstrap_time"` - // DefaultTimeout contains the default timeout for torsf - DefaultTimeout float64 `json:"default_timeout"` + // Error is one of `null`, `"timeout-reached"`, and `"unknown-error"` (this + // field exists for backward compatibility with the previous + // `vanilla_tor` implementation). + Error *string `json:"error"` // Failure contains the failure string or nil. Failure *string `json:"failure"` + // Success indicates whether we succeded (this field exists for + // backward compatibility with the previous `vanilla_tor` implementation). + Success bool `json:"success"` + // PersistentDatadir indicates whether we're using a persistent tor datadir. PersistentDatadir bool `json:"persistent_datadir"` // RendezvousMethod contains the method used to perform the rendezvous. RendezvousMethod string `json:"rendezvous_method"` + // Timeout contains the default timeout for this experiment + Timeout float64 `json:"timeout"` + // TorLogs contains the bootstrap logs. TorLogs []string `json:"tor_logs"` + // TorProgress contains the percentage of the maximum progress reached. + TorProgress int64 `json:"tor_progress"` + + // TorProgressTag contains the tag of the maximum progress reached. + TorProgressTag string `json:"tor_progress_tag"` + + // TorProgressSummary contains the summary of the maximum progress reached. + TorProgressSummary string `json:"tor_progress_summary"` + // TorVersion contains the version of tor (if it's possible to obtain it). TorVersion string `json:"tor_version"` + + // TransportName is always set to "snowflake" for this experiment. + TransportName string `json:"transport_name"` } // Measurer performs the measurement. @@ -91,6 +114,9 @@ func (m *Measurer) registerExtensions(measurement *model.Measurement) { // currently none } +// maxRuntime is the maximum runtime for this experiment +const maxRuntime = 600 * time.Second + // Run runs the experiment with the specified context, session, // measurement, and experiment calbacks. This method should only // return an error in case the experiment could not run (e.g., @@ -110,7 +136,6 @@ func (m *Measurer) Run( defer ptl.Stop() m.registerExtensions(measurement) start := time.Now() - const maxRuntime = 600 * time.Second ctx, cancel := context.WithTimeout(ctx, maxRuntime) defer cancel() tkch := make(chan *TestKeys) @@ -161,15 +186,32 @@ func (m *Measurer) setup(ctx context.Context, return ptl, sfdialer, nil } +// values for the backward compatible error field. +var ( + timeoutReachedError = "timeout-reached" + unknownError = "unknown-error" +) + // bootstrap runs the bootstrap. func (m *Measurer) bootstrap(ctx context.Context, timeout time.Duration, sess model.ExperimentSession, out chan<- *TestKeys, ptl *ptx.Listener, sfdialer *ptx.SnowflakeDialer) { tk := &TestKeys{ - BootstrapTime: 0, - DefaultTimeout: timeout.Seconds(), - Failure: nil, + // initialized later + BootstrapTime: 0, + Error: nil, + Failure: nil, + Success: false, + TorLogs: []string{}, + TorProgress: 0, + TorProgressTag: "", + TorProgressSummary: "", + TorVersion: "", + // initialized now PersistentDatadir: !m.config.DisablePersistentDatadir, RendezvousMethod: sfdialer.RendezvousMethod.Name(), + // + Timeout: timeout.Seconds(), + TransportName: "snowflake", } sess.Logger().Infof( "torsf: disable persistent datadir: %+v", m.config.DisablePersistentDatadir) @@ -192,48 +234,34 @@ func (m *Measurer) bootstrap(ctx context.Context, timeout time.Duration, sess mo if err != nil { // Note: archival.NewFailure scrubs IP addresses tk.Failure = archival.NewFailure(err) + if errors.Is(err, context.DeadlineExceeded) { + tk.Error = &timeoutReachedError + } else { + tk.Error = &unknownError + } + tk.Success = false return } defer tun.Stop() tk.BootstrapTime = tun.BootstrapTime().Seconds() + tk.Success = true } -// torProgressRegexp helps to extract progress info from logs. -// -// See https://regex101.com/r/cer3lm/1. -var torProgressRegexp = regexp.MustCompile( - `^[A-Za-z0-9.: ]+ \[notice\] Bootstrapped [0-9]+% \([A-Za-z_]+\): [A-Za-z0-9 ]+$`) - // readTorLogs attempts to read and include the tor logs into // the test keys if this operation is possible. -// -// This function aims to _only_ include notice information about -// bootstrap according to the torProgressRegexp regexp. -// -// Tor is know to be good software that does not break its output -// unnecessarily and that does not include PII into its logs unless -// explicitly asked to. This fact gives me confidence that we can -// safely include this subset of the logs into the results. -// -// On this note, I think it's safe to include timestamps from the -// logs into the output, since we have a timestamp for the whole -// experiment already, so we don't leak much more by also including -// the Tor proper timestamps into the results. func (m *Measurer) readTorLogs(logger model.Logger, tk *TestKeys, logFilePath string) { - if logFilePath == "" { - log.Warn("the tunnel claims there is no log file") + tk.TorLogs = append(tk.TorLogs, torlogs.ReadBootstrapLogsOrWarn(logger, logFilePath)...) + if len(tk.TorLogs) <= 0 { return } - data, err := os.ReadFile(logFilePath) - if err != nil { - log.Warnf("could not read tor logs: %s", err.Error()) - return - } - for _, bline := range bytes.Split(data, []byte("\n")) { - if torProgressRegexp.Match(bline) { - tk.TorLogs = append(tk.TorLogs, string(bline)) - } - } + last := tk.TorLogs[len(tk.TorLogs)-1] + bi, err := torlogs.ParseBootstrapLogLine(last) + // Implementation note: parsing cannot fail here because we're using the same code + // for selecting and for parsing the bootstrap logs, so we panic on error. + runtimex.PanicOnError(err, fmt.Sprintf("cannot parse bootstrap line: %s", last)) + tk.TorProgress = bi.Progress + tk.TorProgressTag = bi.Tag + tk.TorProgressSummary = bi.Summary } // baseTunnelDir returns the base directory to use for tunnelling diff --git a/internal/engine/experiment/torsf/torsf_test.go b/internal/engine/experiment/torsf/torsf_test.go index 1117840..e71c666 100644 --- a/internal/engine/experiment/torsf/torsf_test.go +++ b/internal/engine/experiment/torsf/torsf_test.go @@ -15,12 +15,17 @@ import ( "github.com/ooni/probe-cli/v3/internal/tunnel/mocks" ) +// Implementation note: this file is written with easy diffing with respect +// to internal/engine/experiment/vanillator/vanillator_test.go in mind. +// +// We may want to have a single implementation for both nettests in the future. + func TestExperimentNameAndVersion(t *testing.T) { m := NewExperimentMeasurer(Config{}) if m.ExperimentName() != "torsf" { t.Fatal("invalid experiment name") } - if m.ExperimentVersion() != "0.2.0" { + if m.ExperimentVersion() != "0.3.0" { t.Fatal("invalid experiment version") } } @@ -113,6 +118,9 @@ func TestSuccessWithMockedTunnelStart(t *testing.T) { if tk.BootstrapTime != bootstrapTime.Seconds() { t.Fatal("unexpected bootstrap time") } + if tk.Error != nil { + t.Fatal("unexpected error") + } if tk.Failure != nil { t.Fatal("unexpected failure") } @@ -122,9 +130,27 @@ func TestSuccessWithMockedTunnelStart(t *testing.T) { if tk.RendezvousMethod != "domain_fronting" { t.Fatal("unexpected rendezvous method") } + if !tk.Success { + t.Fatal("unexpected success value") + } + if tk.Timeout != maxRuntime.Seconds() { + t.Fatal("unexpected timeout") + } if count := len(tk.TorLogs); count != 9 { t.Fatal("unexpected length of tor logs", count) } + if tk.TorProgress != 100 { + t.Fatal("unexpected tor progress") + } + if tk.TorProgressTag != "done" { + t.Fatal("unexpected tor progress tag") + } + if tk.TorProgressSummary != "Done" { + t.Fatal("unexpected tor progress tag") + } + if tk.TransportName != "snowflake" { + t.Fatal("invalid transport name") + } } func TestWithCancelledContext(t *testing.T) { @@ -149,6 +175,9 @@ func TestWithCancelledContext(t *testing.T) { if tk.BootstrapTime != 0 { t.Fatal("unexpected bootstrap time") } + if tk.Error == nil || *tk.Error != "unknown-error" { + t.Fatal("unexpected error") + } if *tk.Failure != "interrupted" { t.Fatal("unexpected failure") } @@ -158,13 +187,31 @@ func TestWithCancelledContext(t *testing.T) { if tk.RendezvousMethod != "domain_fronting" { t.Fatal("unexpected rendezvous method") } + if tk.Success { + t.Fatal("unexpected success value") + } + if tk.Timeout != maxRuntime.Seconds() { + t.Fatal("unexpected timeout") + } if len(tk.TorLogs) != 0 { t.Fatal("unexpected length of tor logs") } + if tk.TorProgress != 0 { + t.Fatal("unexpected tor progress") + } + if tk.TorProgressTag != "" { + t.Fatal("unexpected tor progress tag") + } + if tk.TorProgressSummary != "" { + t.Fatal("unexpected tor progress tag") + } + if tk.TransportName != "snowflake" { + t.Fatal("invalid transport name") + } } func TestFailureToStartTunnel(t *testing.T) { - expected := errors.New("mocked error") + expected := context.DeadlineExceeded // error occurring on bootstrap timeout m := &Measurer{ config: Config{}, mockStartTunnel: func( @@ -172,7 +219,7 @@ func TestFailureToStartTunnel(t *testing.T) { return nil, tunnel.DebugInfo{ Name: "tor", - LogFilePath: filepath.Join("testdata", "tor.log"), + LogFilePath: filepath.Join("testdata", "partial.log"), }, expected }, } @@ -191,10 +238,13 @@ func TestFailureToStartTunnel(t *testing.T) { if tk.BootstrapTime != 0 { t.Fatal("unexpected bootstrap time") } + if tk.Error == nil || *tk.Error != "timeout-reached" { + t.Fatal("unexpected error") + } if tk.Failure == nil { t.Fatal("unexpectedly nil failure string") } - if *tk.Failure != "unknown_failure: mocked error" { + if *tk.Failure != "generic_timeout_error" { t.Fatal("unexpected failure string", *tk.Failure) } if !tk.PersistentDatadir { @@ -203,9 +253,27 @@ func TestFailureToStartTunnel(t *testing.T) { if tk.RendezvousMethod != "domain_fronting" { t.Fatal("unexpected rendezvous method") } - if count := len(tk.TorLogs); count != 9 { + if tk.Success { + t.Fatal("unexpected success value") + } + if tk.Timeout != maxRuntime.Seconds() { + t.Fatal("unexpected timeout") + } + if count := len(tk.TorLogs); count != 6 { t.Fatal("unexpected length of tor logs", count) } + if tk.TorProgress != 15 { + t.Fatal("unexpected tor progress") + } + if tk.TorProgressTag != "handshake_done" { + t.Fatal("unexpected tor progress tag") + } + if tk.TorProgressSummary != "Handshake with a relay done" { + t.Fatal("unexpected tor progress tag") + } + if tk.TransportName != "snowflake" { + t.Fatal("invalid transport name") + } } func TestBaseTunnelDir(t *testing.T) { @@ -242,38 +310,6 @@ func TestBaseTunnelDir(t *testing.T) { }) } -func TestReadTorLogs(t *testing.T) { - t.Run("with empty file path", func(t *testing.T) { - m := &Measurer{} - logger := model.DiscardLogger - tk := &TestKeys{} - m.readTorLogs(logger, tk, "") - if len(tk.TorLogs) != 0 { - t.Fatal("expected no tor logs") - } - }) - - t.Run("with nonexistent file path", func(t *testing.T) { - m := &Measurer{} - logger := model.DiscardLogger - tk := &TestKeys{} - m.readTorLogs(logger, tk, filepath.Join("testdata", "nonexistent")) - if len(tk.TorLogs) != 0 { - t.Fatal("expected no tor logs") - } - }) - - t.Run("with existing file path", func(t *testing.T) { - m := &Measurer{} - logger := model.DiscardLogger - tk := &TestKeys{} - m.readTorLogs(logger, tk, filepath.Join("testdata", "tor.log")) - if count := len(tk.TorLogs); count != 9 { - t.Fatal("unexpected number of tor logs", count) - } - }) -} - func TestGetSummaryKeys(t *testing.T) { t.Run("in case of untyped nil TestKeys", func(t *testing.T) { measurement := &model.Measurement{ diff --git a/internal/engine/experiment/vanillator/integration_test.go b/internal/engine/experiment/vanillator/integration_test.go new file mode 100644 index 0000000..c569303 --- /dev/null +++ b/internal/engine/experiment/vanillator/integration_test.go @@ -0,0 +1,40 @@ +package vanillator_test + +import ( + "context" + "io/ioutil" + "testing" + + "github.com/apex/log" + "github.com/ooni/probe-cli/v3/internal/engine/experiment/vanillator" + "github.com/ooni/probe-cli/v3/internal/engine/mockable" + "github.com/ooni/probe-cli/v3/internal/model" + "golang.org/x/sys/execabs" +) + +func TestRunWithExistingTor(t *testing.T) { + if testing.Short() { + t.Skip("skip test in short mode") + } + path, err := execabs.LookPath("tor") + if err != nil { + t.Skip("there is no tor executable installed") + } + t.Log("found tor in path:", path) + tempdir, err := ioutil.TempDir("", "") + if err != nil { + t.Fatal(err) + } + t.Log("using this tempdir", tempdir) + m := vanillator.NewExperimentMeasurer(vanillator.Config{}) + ctx := context.Background() + measurement := &model.Measurement{} + callbacks := model.NewPrinterCallbacks(log.Log) + sess := &mockable.Session{ + MockableLogger: log.Log, + MockableTempDir: tempdir, + } + if err = m.Run(ctx, sess, measurement, callbacks); err != nil { + t.Fatal(err) + } +} diff --git a/internal/engine/experiment/vanillator/testdata/partial.log b/internal/engine/experiment/vanillator/testdata/partial.log new file mode 100644 index 0000000..37612c2 --- /dev/null +++ b/internal/engine/experiment/vanillator/testdata/partial.log @@ -0,0 +1,27 @@ +Feb 04 15:04:29.000 [notice] Tor 0.4.6.9 opening new log file. +Feb 04 15:04:29.360 [notice] We compiled with OpenSSL 101010cf: OpenSSL 1.1.1l FIPS 24 Aug 2021 and we are running with OpenSSL 101010cf: 1.1.1l. These two versions should be binary compatible. +Feb 04 15:04:29.363 [notice] Tor 0.4.6.9 running on Linux with Libevent 2.1.12-stable, OpenSSL 1.1.1l, Zlib 1.2.11, Liblzma 5.2.5, Libzstd 1.5.2 and Glibc 2.34 as libc. +Feb 04 15:04:29.363 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning +Feb 04 15:04:29.363 [warn] Tor was compiled with zstd 1.5.1, but is running with zstd 1.5.2. For safety, we'll avoid using advanced zstd functionality. +Feb 04 15:04:29.363 [notice] Read configuration file "/home/sbs/.miniooni/tunnel/torsf/tor/torrc-2981077975". +Feb 04 15:04:29.366 [notice] Opening Control listener on 127.0.0.1:0 +Feb 04 15:04:29.367 [notice] Control listener listening on port 41423. +Feb 04 15:04:29.367 [notice] Opened Control listener connection (ready) on 127.0.0.1:41423 +Feb 04 15:04:29.367 [notice] DisableNetwork is set. Tor will not make or accept non-control network connections. Shutting down all existing connections. +Feb 04 15:04:29.000 [notice] Parsing GEOIP IPv4 file /usr/share/tor/geoip. +Feb 04 15:04:29.000 [notice] Parsing GEOIP IPv6 file /usr/share/tor/geoip6. +Feb 04 15:04:29.000 [notice] Bootstrapped 0% (starting): Starting +Feb 04 15:04:29.000 [notice] Starting with guard context "bridges" +Feb 04 15:04:29.000 [notice] new bridge descriptor 'flakey4' (cached): $2B280B23E1107BB62ABFC40DDCC8824814F80A72~flakey4 [1zOHpg+FxqQfi/6jDLtCpHHqBTH8gjYmCKXkus1D5Ko] at 192.0.2.3 +Feb 04 15:04:29.000 [notice] Delaying directory fetches: DisableNetwork is set. +Feb 04 15:04:29.000 [notice] New control connection opened from 127.0.0.1. +Feb 04 15:04:29.000 [notice] Opening Socks listener on 127.0.0.1:0 +Feb 04 15:04:29.000 [notice] Socks listener listening on port 42089. +Feb 04 15:04:29.000 [notice] Opened Socks listener connection (ready) on 127.0.0.1:42089 +Feb 04 15:04:29.000 [notice] Tor 0.4.6.9 opening log file. +Feb 04 15:04:29.000 [notice] Bootstrapped 1% (conn_pt): Connecting to pluggable transport +Feb 04 15:04:30.000 [notice] Bootstrapped 2% (conn_done_pt): Connected to pluggable transport +Feb 04 15:04:30.000 [notice] Bootstrapped 10% (conn_done): Connected to a relay +Feb 04 15:06:20.000 [notice] Bootstrapped 14% (handshake): Handshaking with a relay +Feb 04 15:06:24.000 [notice] Bootstrapped 15% (handshake_done): Handshake with a relay done +Feb 04 15:06:39.000 [notice] Catching signal TERM, exiting cleanly. diff --git a/internal/engine/experiment/vanillator/testdata/tor.log b/internal/engine/experiment/vanillator/testdata/tor.log new file mode 100644 index 0000000..cd5282c --- /dev/null +++ b/internal/engine/experiment/vanillator/testdata/tor.log @@ -0,0 +1,31 @@ +Feb 04 15:04:29.000 [notice] Tor 0.4.6.9 opening new log file. +Feb 04 15:04:29.360 [notice] We compiled with OpenSSL 101010cf: OpenSSL 1.1.1l FIPS 24 Aug 2021 and we are running with OpenSSL 101010cf: 1.1.1l. These two versions should be binary compatible. +Feb 04 15:04:29.363 [notice] Tor 0.4.6.9 running on Linux with Libevent 2.1.12-stable, OpenSSL 1.1.1l, Zlib 1.2.11, Liblzma 5.2.5, Libzstd 1.5.2 and Glibc 2.34 as libc. +Feb 04 15:04:29.363 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning +Feb 04 15:04:29.363 [warn] Tor was compiled with zstd 1.5.1, but is running with zstd 1.5.2. For safety, we'll avoid using advanced zstd functionality. +Feb 04 15:04:29.363 [notice] Read configuration file "/home/sbs/.miniooni/tunnel/torsf/tor/torrc-2981077975". +Feb 04 15:04:29.366 [notice] Opening Control listener on 127.0.0.1:0 +Feb 04 15:04:29.367 [notice] Control listener listening on port 41423. +Feb 04 15:04:29.367 [notice] Opened Control listener connection (ready) on 127.0.0.1:41423 +Feb 04 15:04:29.367 [notice] DisableNetwork is set. Tor will not make or accept non-control network connections. Shutting down all existing connections. +Feb 04 15:04:29.000 [notice] Parsing GEOIP IPv4 file /usr/share/tor/geoip. +Feb 04 15:04:29.000 [notice] Parsing GEOIP IPv6 file /usr/share/tor/geoip6. +Feb 04 15:04:29.000 [notice] Bootstrapped 0% (starting): Starting +Feb 04 15:04:29.000 [notice] Starting with guard context "bridges" +Feb 04 15:04:29.000 [notice] new bridge descriptor 'flakey4' (cached): $2B280B23E1107BB62ABFC40DDCC8824814F80A72~flakey4 [1zOHpg+FxqQfi/6jDLtCpHHqBTH8gjYmCKXkus1D5Ko] at 192.0.2.3 +Feb 04 15:04:29.000 [notice] Delaying directory fetches: DisableNetwork is set. +Feb 04 15:04:29.000 [notice] New control connection opened from 127.0.0.1. +Feb 04 15:04:29.000 [notice] Opening Socks listener on 127.0.0.1:0 +Feb 04 15:04:29.000 [notice] Socks listener listening on port 42089. +Feb 04 15:04:29.000 [notice] Opened Socks listener connection (ready) on 127.0.0.1:42089 +Feb 04 15:04:29.000 [notice] Tor 0.4.6.9 opening log file. +Feb 04 15:04:29.000 [notice] Bootstrapped 1% (conn_pt): Connecting to pluggable transport +Feb 04 15:04:30.000 [notice] Bootstrapped 2% (conn_done_pt): Connected to pluggable transport +Feb 04 15:04:30.000 [notice] Bootstrapped 10% (conn_done): Connected to a relay +Feb 04 15:06:20.000 [notice] Bootstrapped 14% (handshake): Handshaking with a relay +Feb 04 15:06:24.000 [notice] Bootstrapped 15% (handshake_done): Handshake with a relay done +Feb 04 15:06:24.000 [notice] Bootstrapped 75% (enough_dirinfo): Loaded enough directory info to build circuits +Feb 04 15:06:24.000 [notice] Bootstrapped 95% (circuit_create): Establishing a Tor circuit +Feb 04 15:06:26.000 [notice] new bridge descriptor 'flakey4' (fresh): $2B280B23E1107BB62ABFC40DDCC8824814F80A72~flakey4 [1zOHpg+FxqQfi/6jDLtCpHHqBTH8gjYmCKXkus1D5Ko] at 192.0.2.3 +Feb 04 15:06:39.000 [notice] Bootstrapped 100% (done): Done +Feb 04 15:06:39.000 [notice] Catching signal TERM, exiting cleanly. diff --git a/internal/engine/experiment/vanillator/vanillator.go b/internal/engine/experiment/vanillator/vanillator.go new file mode 100644 index 0000000..625a1f0 --- /dev/null +++ b/internal/engine/experiment/vanillator/vanillator.go @@ -0,0 +1,252 @@ +// Package vanillator contains the vanilla_tor experiment. +// +// See https://github.com/ooni/spec/blob/master/nettests/ts-016-vanilla-tor.md +package vanillator + +import ( + "context" + "errors" + "fmt" + "path" + "time" + + "github.com/ooni/probe-cli/v3/internal/engine/netx/archival" + "github.com/ooni/probe-cli/v3/internal/model" + "github.com/ooni/probe-cli/v3/internal/runtimex" + "github.com/ooni/probe-cli/v3/internal/torlogs" + "github.com/ooni/probe-cli/v3/internal/tunnel" +) + +// Implementation note: this file is written with easy diffing with respect +// to internal/engine/experiment/torsf/torsf.go in mind. +// +// We may want to have a single implementation for both nettests in the future. + +// testVersion is the experiment version. +const testVersion = "0.2.0" + +// Config contains the experiment config. +type Config struct { + // DisableProgress disables printing progress messages. + DisableProgress bool `ooni:"Disable printing progress messages"` +} + +// TestKeys contains the experiment's result. +type TestKeys struct { + // BootstrapTime contains the bootstrap time on success. + BootstrapTime float64 `json:"bootstrap_time"` + + // Error is one of `null`, `"timeout-reached"`, and `"unknown-error"` (this + // field exists for backward compatibility with the previous + // `vanilla_tor` implementation). + Error *string `json:"error"` + + // Failure contains the failure string or nil. + Failure *string `json:"failure"` + + // Success indicates whether we succeded (this field exists for + // backward compatibility with the previous `vanilla_tor` implementation). + Success bool `json:"success"` + + // Timeout contains the default timeout for this experiment + Timeout float64 `json:"timeout"` + + // TorLogs contains the bootstrap logs. + TorLogs []string `json:"tor_logs"` + + // TorProgress contains the percentage of the maximum progress reached. + TorProgress int64 `json:"tor_progress"` + + // TorProgressTag contains the tag of the maximum progress reached. + TorProgressTag string `json:"tor_progress_tag"` + + // TorProgressSummary contains the summary of the maximum progress reached. + TorProgressSummary string `json:"tor_progress_summary"` + + // TorVersion contains the version of tor (if it's possible to obtain it). + TorVersion string `json:"tor_version"` + + // TransportName is always set to "vanilla" for this experiment. + TransportName string `json:"transport_name"` +} + +// Measurer performs the measurement. +type Measurer struct { + // config contains the experiment settings. + config Config + + // mockStartTunnel is an optional function that allows us to override the + // default tunnel.Start function used to start a tunnel. + mockStartTunnel func( + ctx context.Context, config *tunnel.Config) (tunnel.Tunnel, tunnel.DebugInfo, error) +} + +// ExperimentName implements model.ExperimentMeasurer.ExperimentName. +func (m *Measurer) ExperimentName() string { + return "vanilla_tor" +} + +// ExperimentVersion implements model.ExperimentMeasurer.ExperimentVersion. +func (m *Measurer) ExperimentVersion() string { + return testVersion +} + +// registerExtensions registers the extensions used by this experiment. +func (m *Measurer) registerExtensions(measurement *model.Measurement) { + // currently none +} + +// maxRuntime is the maximum runtime for this experiment +const maxRuntime = 200 * time.Second + +// Run runs the experiment with the specified context, session, +// measurement, and experiment calbacks. This method should only +// return an error in case the experiment could not run (e.g., +// a required input is missing). Otherwise, the code should just +// set the relevant OONI error inside of the measurement and +// return nil. This is important because the caller may not submit +// the measurement if this method returns an error. +func (m *Measurer) Run( + ctx context.Context, sess model.ExperimentSession, + measurement *model.Measurement, callbacks model.ExperimentCallbacks, +) error { + m.registerExtensions(measurement) + start := time.Now() + ctx, cancel := context.WithTimeout(ctx, maxRuntime) + defer cancel() + tkch := make(chan *TestKeys) + ticker := time.NewTicker(2 * time.Second) + defer ticker.Stop() + go m.bootstrap(ctx, maxRuntime, sess, tkch) + for { + select { + case tk := <-tkch: + measurement.TestKeys = tk + callbacks.OnProgress(1.0, "vanilla_tor experiment is finished") + return nil + case <-ticker.C: + if !m.config.DisableProgress { + elapsedTime := time.Since(start) + progress := elapsedTime.Seconds() / maxRuntime.Seconds() + callbacks.OnProgress(progress, fmt.Sprintf( + "vanilla_tor: elapsedTime: %.0f s; maxRuntime: %.0f s", + elapsedTime.Seconds(), maxRuntime.Seconds())) + } + } + } +} + +// values for the backward compatible error field. +var ( + timeoutReachedError = "timeout-reached" + unknownError = "unknown-error" +) + +// bootstrap runs the bootstrap. +func (m *Measurer) bootstrap(ctx context.Context, timeout time.Duration, + sess model.ExperimentSession, out chan<- *TestKeys) { + tk := &TestKeys{ + // initialized later + BootstrapTime: 0, + Error: nil, + Failure: nil, + Success: false, + TorLogs: []string{}, + TorProgress: 0, + TorProgressTag: "", + TorProgressSummary: "", + TorVersion: "", + // initialized now + Timeout: timeout.Seconds(), + TransportName: "vanilla", + } + defer func() { + out <- tk + }() + tun, debugInfo, err := m.startTunnel()(ctx, &tunnel.Config{ + Name: "tor", + Session: sess, + TunnelDir: path.Join(m.baseTunnelDir(sess), "vanillator"), + Logger: sess.Logger(), + }) + tk.TorVersion = debugInfo.Version + m.readTorLogs(sess.Logger(), tk, debugInfo.LogFilePath) + if err != nil { + // Note: archival.NewFailure scrubs IP addresses + tk.Failure = archival.NewFailure(err) + if errors.Is(err, context.DeadlineExceeded) { + tk.Error = &timeoutReachedError + } else { + tk.Error = &unknownError + } + tk.Success = false + return + } + defer tun.Stop() + tk.BootstrapTime = tun.BootstrapTime().Seconds() + tk.Success = true +} + +// readTorLogs attempts to read and include the tor logs into +// the test keys if this operation is possible. +func (m *Measurer) readTorLogs(logger model.Logger, tk *TestKeys, logFilePath string) { + tk.TorLogs = append(tk.TorLogs, torlogs.ReadBootstrapLogsOrWarn(logger, logFilePath)...) + if len(tk.TorLogs) <= 0 { + return + } + last := tk.TorLogs[len(tk.TorLogs)-1] + bi, err := torlogs.ParseBootstrapLogLine(last) + // Implementation note: parsing cannot fail here because we're using the same code + // for selecting and for parsing the bootstrap logs, so we panic on error. + runtimex.PanicOnError(err, fmt.Sprintf("cannot parse bootstrap line: %s", last)) + tk.TorProgress = bi.Progress + tk.TorProgressTag = bi.Tag + tk.TorProgressSummary = bi.Summary +} + +// baseTunnelDir returns the base directory to use for tunnelling +func (m *Measurer) baseTunnelDir(sess model.ExperimentSession) string { + return sess.TempDir() +} + +// startTunnel returns the proper function to start a tunnel. +func (m *Measurer) startTunnel() func( + ctx context.Context, config *tunnel.Config) (tunnel.Tunnel, tunnel.DebugInfo, error) { + if m.mockStartTunnel != nil { + return m.mockStartTunnel + } + return tunnel.Start +} + +// NewExperimentMeasurer creates a new ExperimentMeasurer. +func NewExperimentMeasurer(config Config) model.ExperimentMeasurer { + return &Measurer{config: config} +} + +// SummaryKeys contains summary keys for this experiment. +// +// Note that this structure is part of the ABI contract with ooniprobe +// therefore we should be careful when changing it. +type SummaryKeys struct { + IsAnomaly bool `json:"-"` +} + +var ( + // errInvalidTestKeysType indicates the test keys type is invalid. + errInvalidTestKeysType = errors.New("vanilla_tor: invalid test keys type") + + //errNilTestKeys indicates that the test keys are nil. + errNilTestKeys = errors.New("vanilla_tor: nil test keys") +) + +// GetSummaryKeys implements model.ExperimentMeasurer.GetSummaryKeys. +func (m *Measurer) GetSummaryKeys(measurement *model.Measurement) (interface{}, error) { + testkeys, good := measurement.TestKeys.(*TestKeys) + if !good { + return nil, errInvalidTestKeysType + } + if testkeys == nil { + return nil, errNilTestKeys + } + return SummaryKeys{IsAnomaly: testkeys.Failure != nil}, nil +} diff --git a/internal/engine/experiment/vanillator/vanillator_test.go b/internal/engine/experiment/vanillator/vanillator_test.go new file mode 100644 index 0000000..e8cbdd4 --- /dev/null +++ b/internal/engine/experiment/vanillator/vanillator_test.go @@ -0,0 +1,281 @@ +package vanillator + +import ( + "context" + "errors" + "path/filepath" + "testing" + "time" + + "github.com/ooni/probe-cli/v3/internal/atomicx" + "github.com/ooni/probe-cli/v3/internal/engine/mockable" + "github.com/ooni/probe-cli/v3/internal/model" + "github.com/ooni/probe-cli/v3/internal/tunnel" + "github.com/ooni/probe-cli/v3/internal/tunnel/mocks" +) + +// Implementation note: this file is written with easy diffing with respect +// to internal/engine/experiment/torsf/torsf_test.go in mind. +// +// We may want to have a single implementation for both nettests in the future. + +func TestExperimentNameAndVersion(t *testing.T) { + m := NewExperimentMeasurer(Config{}) + if m.ExperimentName() != "vanilla_tor" { + t.Fatal("invalid experiment name") + } + if m.ExperimentVersion() != "0.2.0" { + t.Fatal("invalid experiment version") + } +} + +func TestSuccessWithMockedTunnelStart(t *testing.T) { + bootstrapTime := 3 * time.Second + called := &atomicx.Int64{} + m := &Measurer{ + config: Config{}, + mockStartTunnel: func( + ctx context.Context, config *tunnel.Config) (tunnel.Tunnel, tunnel.DebugInfo, error) { + // run for some time so we also exercise printing progress. + time.Sleep(bootstrapTime) + return &mocks.Tunnel{ + MockBootstrapTime: func() time.Duration { + return bootstrapTime + }, + MockStop: func() { + called.Add(1) + }, + }, tunnel.DebugInfo{ + Name: "tor", + LogFilePath: filepath.Join("testdata", "tor.log"), + }, nil + }, + } + ctx := context.Background() + measurement := &model.Measurement{} + sess := &mockable.Session{ + MockableLogger: model.DiscardLogger, + } + callbacks := &model.PrinterCallbacks{ + Logger: model.DiscardLogger, + } + if err := m.Run(ctx, sess, measurement, callbacks); err != nil { + t.Fatal(err) + } + if called.Load() != 1 { + t.Fatal("stop was not called") + } + tk := measurement.TestKeys.(*TestKeys) + if tk.BootstrapTime != bootstrapTime.Seconds() { + t.Fatal("unexpected bootstrap time") + } + if tk.Error != nil { + t.Fatal("unexpected error") + } + if tk.Failure != nil { + t.Fatal("unexpected failure") + } + if !tk.Success { + t.Fatal("unexpected success value") + } + if tk.Timeout != maxRuntime.Seconds() { + t.Fatal("unexpected timeout") + } + if count := len(tk.TorLogs); count != 9 { + t.Fatal("unexpected length of tor logs", count) + } + if tk.TorProgress != 100 { + t.Fatal("unexpected tor progress") + } + if tk.TorProgressTag != "done" { + t.Fatal("unexpected tor progress tag") + } + if tk.TorProgressSummary != "Done" { + t.Fatal("unexpected tor progress tag") + } + if tk.TransportName != "vanilla" { + t.Fatal("invalid transport name") + } +} + +func TestWithCancelledContext(t *testing.T) { + // This test calls the real tunnel.Start function so we cover + // it but fails immediately because of the cancelled ctx. + m := &Measurer{ + config: Config{}, + } + ctx, cancel := context.WithCancel(context.Background()) + cancel() // fail immediately + measurement := &model.Measurement{} + sess := &mockable.Session{ + MockableLogger: model.DiscardLogger, + } + callbacks := &model.PrinterCallbacks{ + Logger: model.DiscardLogger, + } + if err := m.Run(ctx, sess, measurement, callbacks); err != nil { + t.Fatal(err) + } + tk := measurement.TestKeys.(*TestKeys) + if tk.BootstrapTime != 0 { + t.Fatal("unexpected bootstrap time") + } + if tk.Error == nil || *tk.Error != "unknown-error" { + t.Fatal("unexpected error") + } + if *tk.Failure != "interrupted" { + t.Fatal("unexpected failure") + } + if tk.Success { + t.Fatal("unexpected success value") + } + if tk.Timeout != maxRuntime.Seconds() { + t.Fatal("unexpected timeout") + } + if len(tk.TorLogs) != 0 { + t.Fatal("unexpected length of tor logs") + } + if tk.TorProgress != 0 { + t.Fatal("unexpected tor progress") + } + if tk.TorProgressTag != "" { + t.Fatal("unexpected tor progress tag") + } + if tk.TorProgressSummary != "" { + t.Fatal("unexpected tor progress tag") + } + if tk.TransportName != "vanilla" { + t.Fatal("invalid transport name") + } +} + +func TestFailureToStartTunnel(t *testing.T) { + expected := context.DeadlineExceeded // error occurring on bootstrap timeout + m := &Measurer{ + config: Config{}, + mockStartTunnel: func( + ctx context.Context, config *tunnel.Config) (tunnel.Tunnel, tunnel.DebugInfo, error) { + return nil, + tunnel.DebugInfo{ + Name: "tor", + LogFilePath: filepath.Join("testdata", "partial.log"), + }, expected + }, + } + ctx := context.Background() + measurement := &model.Measurement{} + sess := &mockable.Session{ + MockableLogger: model.DiscardLogger, + } + callbacks := &model.PrinterCallbacks{ + Logger: model.DiscardLogger, + } + if err := m.Run(ctx, sess, measurement, callbacks); err != nil { + t.Fatal(err) + } + tk := measurement.TestKeys.(*TestKeys) + if tk.BootstrapTime != 0 { + t.Fatal("unexpected bootstrap time") + } + if tk.Error == nil || *tk.Error != "timeout-reached" { + t.Fatal("unexpected error") + } + if tk.Failure == nil { + t.Fatal("unexpectedly nil failure string") + } + if *tk.Failure != "generic_timeout_error" { + t.Fatal("unexpected failure string", *tk.Failure) + } + if tk.Success { + t.Fatal("unexpected success value") + } + if tk.Timeout != maxRuntime.Seconds() { + t.Fatal("unexpected timeout") + } + if count := len(tk.TorLogs); count != 6 { + t.Fatal("unexpected length of tor logs", count) + } + if tk.TorProgress != 15 { + t.Fatal("unexpected tor progress") + } + if tk.TorProgressTag != "handshake_done" { + t.Fatal("unexpected tor progress tag") + } + if tk.TorProgressSummary != "Handshake with a relay done" { + t.Fatal("unexpected tor progress tag") + } + if tk.TransportName != "vanilla" { + t.Fatal("invalid transport name") + } +} + +func TestGetSummaryKeys(t *testing.T) { + t.Run("in case of untyped nil TestKeys", func(t *testing.T) { + measurement := &model.Measurement{ + TestKeys: nil, + } + m := &Measurer{} + _, err := m.GetSummaryKeys(measurement) + if !errors.Is(err, errInvalidTestKeysType) { + t.Fatal("unexpected error", err) + } + }) + + t.Run("in case of typed nil TestKeys", func(t *testing.T) { + var tk *TestKeys + measurement := &model.Measurement{ + TestKeys: tk, + } + m := &Measurer{} + _, err := m.GetSummaryKeys(measurement) + if !errors.Is(err, errNilTestKeys) { + t.Fatal("unexpected error", err) + } + }) + + t.Run("in case of invalid TestKeys type", func(t *testing.T) { + measurement := &model.Measurement{ + TestKeys: make(chan int), + } + m := &Measurer{} + _, err := m.GetSummaryKeys(measurement) + if !errors.Is(err, errInvalidTestKeysType) { + t.Fatal("unexpected error", err) + } + }) + + t.Run("in case of success", func(t *testing.T) { + measurement := &model.Measurement{ + TestKeys: &TestKeys{ + Failure: nil, + }, + } + m := &Measurer{} + sk, err := m.GetSummaryKeys(measurement) + if err != nil { + t.Fatal(err) + } + rsk := sk.(SummaryKeys) + if rsk.IsAnomaly { + t.Fatal("expected no anomaly here") + } + }) + + t.Run("in case of failure", func(t *testing.T) { + failure := "generic_timeout_error" + measurement := &model.Measurement{ + TestKeys: &TestKeys{ + Failure: &failure, + }, + } + m := &Measurer{} + sk, err := m.GetSummaryKeys(measurement) + if err != nil { + t.Fatal(err) + } + rsk := sk.(SummaryKeys) + if !rsk.IsAnomaly { + t.Fatal("expected anomaly here") + } + }) +} diff --git a/internal/model/mocks/logger.go b/internal/model/mocks/logger.go index d6696af..f845fdd 100644 --- a/internal/model/mocks/logger.go +++ b/internal/model/mocks/logger.go @@ -2,9 +2,12 @@ package mocks // Logger allows mocking a logger. type Logger struct { - MockDebug func(message string) - + MockDebug func(message string) MockDebugf func(format string, v ...interface{}) + MockInfo func(message string) + MockInfof func(format string, v ...interface{}) + MockWarn func(message string) + MockWarnf func(format string, v ...interface{}) } // Debug calls MockDebug. @@ -16,3 +19,23 @@ func (lo *Logger) Debug(message string) { func (lo *Logger) Debugf(format string, v ...interface{}) { lo.MockDebugf(format, v...) } + +// Info calls MockInfo. +func (lo *Logger) Info(message string) { + lo.MockInfo(message) +} + +// Infof calls MockInfof. +func (lo *Logger) Infof(format string, v ...interface{}) { + lo.MockInfof(format, v...) +} + +// Warn calls MockWarn. +func (lo *Logger) Warn(message string) { + lo.MockWarn(message) +} + +// Warnf calls MockWarnf. +func (lo *Logger) Warnf(format string, v ...interface{}) { + lo.MockWarnf(format, v...) +} diff --git a/internal/model/mocks/logger_test.go b/internal/model/mocks/logger_test.go index 6572b10..b02025b 100644 --- a/internal/model/mocks/logger_test.go +++ b/internal/model/mocks/logger_test.go @@ -28,4 +28,56 @@ func TestLogger(t *testing.T) { t.Fatal("not called") } }) + + t.Run("Info", func(t *testing.T) { + var called bool + lo := &Logger{ + MockInfo: func(message string) { + called = true + }, + } + lo.Info("antani") + if !called { + t.Fatal("not called") + } + }) + + t.Run("Infof", func(t *testing.T) { + var called bool + lo := &Logger{ + MockInfof: func(message string, v ...interface{}) { + called = true + }, + } + lo.Infof("antani", 1, 2, 3, 4) + if !called { + t.Fatal("not called") + } + }) + + t.Run("Warn", func(t *testing.T) { + var called bool + lo := &Logger{ + MockWarn: func(message string) { + called = true + }, + } + lo.Warn("antani") + if !called { + t.Fatal("not called") + } + }) + + t.Run("Warnf", func(t *testing.T) { + var called bool + lo := &Logger{ + MockWarnf: func(message string, v ...interface{}) { + called = true + }, + } + lo.Warnf("antani", 1, 2, 3, 4) + if !called { + t.Fatal("not called") + } + }) } diff --git a/internal/torlogs/testdata/empty.log b/internal/torlogs/testdata/empty.log new file mode 100644 index 0000000..e69de29 diff --git a/internal/torlogs/testdata/tor.log b/internal/torlogs/testdata/tor.log new file mode 100644 index 0000000..cd5282c --- /dev/null +++ b/internal/torlogs/testdata/tor.log @@ -0,0 +1,31 @@ +Feb 04 15:04:29.000 [notice] Tor 0.4.6.9 opening new log file. +Feb 04 15:04:29.360 [notice] We compiled with OpenSSL 101010cf: OpenSSL 1.1.1l FIPS 24 Aug 2021 and we are running with OpenSSL 101010cf: 1.1.1l. These two versions should be binary compatible. +Feb 04 15:04:29.363 [notice] Tor 0.4.6.9 running on Linux with Libevent 2.1.12-stable, OpenSSL 1.1.1l, Zlib 1.2.11, Liblzma 5.2.5, Libzstd 1.5.2 and Glibc 2.34 as libc. +Feb 04 15:04:29.363 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning +Feb 04 15:04:29.363 [warn] Tor was compiled with zstd 1.5.1, but is running with zstd 1.5.2. For safety, we'll avoid using advanced zstd functionality. +Feb 04 15:04:29.363 [notice] Read configuration file "/home/sbs/.miniooni/tunnel/torsf/tor/torrc-2981077975". +Feb 04 15:04:29.366 [notice] Opening Control listener on 127.0.0.1:0 +Feb 04 15:04:29.367 [notice] Control listener listening on port 41423. +Feb 04 15:04:29.367 [notice] Opened Control listener connection (ready) on 127.0.0.1:41423 +Feb 04 15:04:29.367 [notice] DisableNetwork is set. Tor will not make or accept non-control network connections. Shutting down all existing connections. +Feb 04 15:04:29.000 [notice] Parsing GEOIP IPv4 file /usr/share/tor/geoip. +Feb 04 15:04:29.000 [notice] Parsing GEOIP IPv6 file /usr/share/tor/geoip6. +Feb 04 15:04:29.000 [notice] Bootstrapped 0% (starting): Starting +Feb 04 15:04:29.000 [notice] Starting with guard context "bridges" +Feb 04 15:04:29.000 [notice] new bridge descriptor 'flakey4' (cached): $2B280B23E1107BB62ABFC40DDCC8824814F80A72~flakey4 [1zOHpg+FxqQfi/6jDLtCpHHqBTH8gjYmCKXkus1D5Ko] at 192.0.2.3 +Feb 04 15:04:29.000 [notice] Delaying directory fetches: DisableNetwork is set. +Feb 04 15:04:29.000 [notice] New control connection opened from 127.0.0.1. +Feb 04 15:04:29.000 [notice] Opening Socks listener on 127.0.0.1:0 +Feb 04 15:04:29.000 [notice] Socks listener listening on port 42089. +Feb 04 15:04:29.000 [notice] Opened Socks listener connection (ready) on 127.0.0.1:42089 +Feb 04 15:04:29.000 [notice] Tor 0.4.6.9 opening log file. +Feb 04 15:04:29.000 [notice] Bootstrapped 1% (conn_pt): Connecting to pluggable transport +Feb 04 15:04:30.000 [notice] Bootstrapped 2% (conn_done_pt): Connected to pluggable transport +Feb 04 15:04:30.000 [notice] Bootstrapped 10% (conn_done): Connected to a relay +Feb 04 15:06:20.000 [notice] Bootstrapped 14% (handshake): Handshaking with a relay +Feb 04 15:06:24.000 [notice] Bootstrapped 15% (handshake_done): Handshake with a relay done +Feb 04 15:06:24.000 [notice] Bootstrapped 75% (enough_dirinfo): Loaded enough directory info to build circuits +Feb 04 15:06:24.000 [notice] Bootstrapped 95% (circuit_create): Establishing a Tor circuit +Feb 04 15:06:26.000 [notice] new bridge descriptor 'flakey4' (fresh): $2B280B23E1107BB62ABFC40DDCC8824814F80A72~flakey4 [1zOHpg+FxqQfi/6jDLtCpHHqBTH8gjYmCKXkus1D5Ko] at 192.0.2.3 +Feb 04 15:06:39.000 [notice] Bootstrapped 100% (done): Done +Feb 04 15:06:39.000 [notice] Catching signal TERM, exiting cleanly. diff --git a/internal/torlogs/torlogs.go b/internal/torlogs/torlogs.go new file mode 100644 index 0000000..6cd2a27 --- /dev/null +++ b/internal/torlogs/torlogs.go @@ -0,0 +1,105 @@ +// Package torlogs contains code to read tor logs. +package torlogs + +import ( + "bytes" + "errors" + "fmt" + "os" + "regexp" + "strconv" + + "github.com/ooni/probe-cli/v3/internal/model" +) + +var ( + // ErrEmptyLogFilePath indicates that the log file path is empty. + ErrEmptyLogFilePath = errors.New("torlogs: empty log file path") + + // ErrCannotReadLogFile indicates we cannot read the log file. + ErrCannotReadLogFile = errors.New("torlogs: cannot read the log file") + + // ErrNoBootstrapLogs indicates we could not find any bootstrap log in the log file. + ErrNoBootstrapLogs = errors.New("torlogs: no bootstrap logs") + + // ErrCannotFindSubmatches indicates we cannot find submatches. + ErrCannotFindSubmatches = errors.New("torlogs: cannot find submatches") +) + +// torBootstrapRegexp helps to extract progress info from logs. +// +// See https://regex101.com/r/Do07qd/1. +var torBootstrapRegexp = regexp.MustCompile( + `^[A-Za-z0-9.: ]+ \[notice\] Bootstrapped ([0-9]+)% \(([A-Za-z_]+)\): ([A-Za-z0-9 ]+)$`) + +// ReadBootstrapLogs reads tor logs from the given file and +// returns a list of bootstrap-related logs. +func ReadBootstrapLogs(logFilePath string) ([]string, error) { + // Implementation note: + // + // Tor is know to be good software that does not break its output + // unnecessarily and that does not include PII into its logs unless + // explicitly asked to. This fact gives me confidence that we can + // safely include this subset of the logs into the results. + // + // On this note, I think it's safe to include timestamps from the + // logs into the output, since we have a timestamp for the whole + // experiment already, so we don't leak much more by also including + // the Tor proper timestamps into the results. + if logFilePath == "" { + return nil, ErrEmptyLogFilePath + } + data, err := os.ReadFile(logFilePath) + if err != nil { + return nil, fmt.Errorf("%w: %s", ErrCannotReadLogFile, err.Error()) + } + var out []string + for _, bline := range bytes.Split(data, []byte("\n")) { + if torBootstrapRegexp.Match(bline) { + out = append(out, string(bline)) + } + } + if len(out) <= 0 { + return nil, ErrNoBootstrapLogs + } + return out, nil +} + +// ReadBootstrapLogsOrWarn is like ReadBootstrapLogs except that it does +// not return an error on failure, rather it emits a warning. +func ReadBootstrapLogsOrWarn(logger model.Logger, logFilePath string) []string { + logs, err := ReadBootstrapLogs(logFilePath) + if err != nil { + logger.Warnf("%s", err.Error()) + return nil + } + return logs +} + +// BootstrapInfo contains info extracted from a bootstrap log line. +type BootstrapInfo struct { + // Progress is the progress (between 0 and 100) + Progress int64 + + // Tag is the machine readable description of the bootstrap state. + Tag string + + // Summary is the human readable summary. + Summary string +} + +// ParseBootstrapLogLine takes in input a bootstrap log line and returns +// in output the components of such a log line. +func ParseBootstrapLogLine(logLine string) (*BootstrapInfo, error) { + values := torBootstrapRegexp.FindStringSubmatch(logLine) + if len(values) != 4 { + return nil, ErrCannotFindSubmatches + } + progress, _ := strconv.ParseInt(values[1], 10, 64) + bi := &BootstrapInfo{ + Progress: progress, + Tag: values[2], + Summary: values[3], + } + return bi, nil +} diff --git a/internal/torlogs/torlogs_test.go b/internal/torlogs/torlogs_test.go new file mode 100644 index 0000000..b44a29b --- /dev/null +++ b/internal/torlogs/torlogs_test.go @@ -0,0 +1,121 @@ +package torlogs + +import ( + "errors" + "path/filepath" + "testing" + + "github.com/google/go-cmp/cmp" + "github.com/ooni/probe-cli/v3/internal/model" + "github.com/ooni/probe-cli/v3/internal/model/mocks" +) + +func TestReadBootstrapLogs(t *testing.T) { + t.Run("with empty file path", func(t *testing.T) { + out, err := ReadBootstrapLogs("") + if !errors.Is(err, ErrEmptyLogFilePath) { + t.Fatal("unexpected err", err) + } + if len(out) > 0 { + t.Fatal("expected no tor logs") + } + }) + + t.Run("with nonexistent file path", func(t *testing.T) { + out, err := ReadBootstrapLogs(filepath.Join("testdata", "nonexistent")) + if !errors.Is(err, ErrCannotReadLogFile) { + t.Fatal("unexpected err", err) + } + if len(out) != 0 { + t.Fatal("expected no tor logs") + } + }) + + t.Run("with existing file path not containing bootstrap logs", func(t *testing.T) { + out, err := ReadBootstrapLogs(filepath.Join("testdata", "empty.log")) + if !errors.Is(err, ErrNoBootstrapLogs) { + t.Fatal("unexpected err", err) + } + if len(out) != 0 { + t.Fatal("expected no tor logs") + } + }) + + t.Run("with existing file path containing bootstrap logs", func(t *testing.T) { + out, err := ReadBootstrapLogs(filepath.Join("testdata", "tor.log")) + if err != nil { + t.Fatal(err) + } + if count := len(out); count != 9 { + t.Fatal("unexpected number of tor logs", count) + } + }) +} + +func TestReadBootstrapLogsOrWarn(t *testing.T) { + t.Run("on success", func(t *testing.T) { + filename := filepath.Join("testdata", "tor.log") + logs := ReadBootstrapLogsOrWarn(model.DiscardLogger, filename) + if count := len(logs); count != 9 { + t.Fatal("unexpected number of tor logs", count) + } + }) + + t.Run("on failure", func(t *testing.T) { + var called bool + logger := &mocks.Logger{ + MockWarnf: func(format string, v ...interface{}) { + called = true + }, + } + filename := filepath.Join("testdata", "empty.log") + logs := ReadBootstrapLogsOrWarn(logger, filename) + if !called { + t.Fatal("not called") + } + if len(logs) != 0 { + t.Fatal("expected no tor logs") + } + }) +} + +func TestParseBootstrapLogLine(t *testing.T) { + type args struct { + logLine string + } + tests := []struct { + name string + args args + want *BootstrapInfo + wantErr error + }{{ + name: "with empty string", + args: args{ + logLine: "", + }, + want: nil, + wantErr: ErrCannotFindSubmatches, + }, { + name: "with correct line", + args: args{ + logLine: "May 10 09:19:28.000 [notice] Bootstrapped 80% (ap_conn): Connecting to a relay to build circuits", + }, + want: &BootstrapInfo{ + Progress: 80, + Tag: "ap_conn", + Summary: "Connecting to a relay to build circuits", + }, + wantErr: nil, + }} + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + got, err := ParseBootstrapLogLine(tt.args.logLine) + if !errors.Is(err, tt.wantErr) { + t.Fatal("unexpected err", err) + } + if diff := cmp.Diff(tt.want, got); diff != "" { + t.Fatal(diff) + } + }) + } +}