c/ooni-probe-cli
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

feat: re-implement the vanilla_tor experiment (#718)

Browse Source 
This diff re-implements the vanilla_tor experiment. This experiment was
part of the ooni/probe-legacy implementation.

The reference issue is https://github.com/ooni/probe/issues/803. We didn't
consider the possible improvements mentioned by the
https://github.com/ooni/probe/issues/803#issuecomment-598715694 comment,
which means we'll need to create a follow-up issue for them. We will
then decide whether, when, and how to implement those follow-up measurements
either into `vanilla_tor` or into the existing `tor` experiment.

This novel `vanilla_tor` implementation emits test_keys that are mostly
compatible with the original implementation, however:

1. the `timeout` is a `float64` rather than integer (but the default
timeout is an integer, so there are no JSON-visible changes);

2. the `tor_log` string is gone and replaced by the `tor_logs` list
of strings, which contains the same information;

3. the definition of `error` has been augmented to include the
case in which there is an unknown error;

4. the implementation of vanilla_tor mirrors closely the one of torsf
and we have taken steps to make the two implementations as comparable
as possible in terms of the generated JSON measurement.

The main reason why we replaced `tor_log` with `tor_logs` are:

1. that `torsf` already used that;

2. that reading the JSON is easier with this implementation compared to
an implementation where all logs are into the same string.

If one is processing the new data format using Python, then it will
not be difficult convert `tor_log` to `tor_logs`. In any case, because
we extract the most interesting fields (e.g., the percentage of the
bootstrap where tor fails), it seems that logs are probably more useful
as something you want to read in edge cases (I guess).

Also, because we want `torsf` and `vanilla_tor` to have similar JSONs,
we renamed `torsf`'s `default_timeout` to `timeout`. This change has little
to none real-world impact, because no stable version of OONI Probe has
ever shipped a `torsf` producing the `default_timeout` field.

Regarding the structure of this diff, we have:

1. factored code to parse tor logs into a separate package;

2. implemented `vanilla_tor` as a stripped down `torsf` and added further
changes to ensure compatibility with the previous `vanilla_tor`'s data format;

3. improved `torsf` to merge back the changes in `vanilla_tor`, so the two
data formats of the two experiments are as similar as possible.

We believe producing as similar as possible data formats helps anyone who's
reading measurements generated by both experiments.

We have retained/introduced `vanilla_tor`'s `error` field, which is not very
useful when one has a more precise failure but is still what `vanilla_tor`
used to emit, so it makes sense to also have this field.

In addition to changing the implementation, we also updated the specs.

As part of our future work, we may want to consider factoring the common code
of these two experiments into the same underlying support library.
This commit is contained in:
Simone Basso 2022-05-10 15:43:28 +02:00 committed by GitHub
parent 3d81845614
commit b7cc309901
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
15 changed files with 1151 additions and 84 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

13
internal/engine/allexperiments.go
View File

@ -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 {

27
internal/engine/experiment/torsf/testdata/partial.log vendored Normal file
View File

@ -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.

118
internal/engine/experiment/torsf/torsf.go
View File

@ -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

110
internal/engine/experiment/torsf/torsf_test.go
View File

@ -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{

40
internal/engine/experiment/vanillator/integration_test.go Normal file
View File

@ -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)
}
}

27
internal/engine/experiment/vanillator/testdata/partial.log vendored Normal file
View File

@ -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.

31
internal/engine/experiment/vanillator/testdata/tor.log vendored Normal file
View File

@ -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.

252
internal/engine/experiment/vanillator/vanillator.go Normal file
View File

@ -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
}

281
internal/engine/experiment/vanillator/vanillator_test.go Normal file
View File

@ -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")
}
})
}

27
internal/model/mocks/logger.go
View File

@ -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...)
}

52
internal/model/mocks/logger_test.go
View File

@ -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")
}
})
}

0
internal/torlogs/testdata/empty.log vendored Normal file
View File

31
internal/torlogs/testdata/tor.log vendored Normal file
View File

@ -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.

105
internal/torlogs/torlogs.go Normal file
View File

@ -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
}

121
internal/torlogs/torlogs_test.go Normal file
View File

@ -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)
}
})
}
}