fix(logx): log when an operation is starting (#1350)

Not logging when an operation is starting complicates reasoning about
how much time it took to fail, which is something that caused issues
investigating ooni/probe#2544.

internal/logx/operation.go

@@ -27,6 +27,7 @@ func newOperationLogger(maxwait time.Duration, logger model.Logger, format strin
 		wg:      &sync.WaitGroup{},
 	}
 	ol.wg.Add(1)
+	ol.logger.Infof("%s... started", ol.message)
 	go ol.maybeEmitProgress()
 	return ol
 }

internal/logx/operation_test.go

@@ -26,10 +26,13 @@ func TestNewOperationLogger(t *testing.T) {
 		}
 		ol := NewOperationLogger(logger, "antani%d", 0)
 		ol.Stop(nil)
-		if len(lines) != 1 {
+		if len(lines) != 2 {
 			t.Fatal("unexpected number of lines")
 		}
-		if lines[0] != "antani0... ok" {
+		if lines[0] != "antani0... started" {
+			t.Fatal("unexpected first line", lines[0])
+		}
+		if lines[1] != "antani0... ok" {
 			t.Fatal("unexpected first line", lines[0])
 		}
 	})
@@ -49,10 +52,13 @@ func TestNewOperationLogger(t *testing.T) {
 		}
 		ol := NewOperationLogger(logger, "antani%d", 0)
 		ol.Stop(io.EOF)
-		if len(lines) != 1 {
+		if len(lines) != 2 {
 			t.Fatal("unexpected number of lines")
 		}
-		if lines[0] != "antani0... EOF" {
+		if lines[0] != "antani0... started" {
+			t.Fatal("unexpected first line", lines[0])
+		}
+		if lines[1] != "antani0... EOF" {
 			t.Fatal("unexpected first line", lines[0])
 		}
 	})
@@ -74,13 +80,16 @@ func TestNewOperationLogger(t *testing.T) {
 		ol := newOperationLogger(maxwait, logger, "antani%d", 0)
 		ol.wg.Wait() // wait for the message to be emitted
 		ol.Stop(nil)
-		if len(lines) != 2 {
+		if len(lines) != 3 {
 			t.Fatal("unexpected number of lines")
 		}
-		if lines[0] != "antani0... in progress" {
+		if lines[0] != "antani0... started" {
 			t.Fatal("unexpected first line", lines[0])
 		}
-		if lines[1] != "antani0... ok" {
+		if lines[1] != "antani0... in progress" {
+			t.Fatal("unexpected first line", lines[0])
+		}
+		if lines[2] != "antani0... ok" {
 			t.Fatal("unexpected first line", lines[0])
 		}
 	})
@@ -102,13 +111,16 @@ func TestNewOperationLogger(t *testing.T) {
 		ol := newOperationLogger(maxwait, logger, "antani%d", 0)
 		ol.wg.Wait() // wait for the message to be emitted
 		ol.Stop(io.EOF)
-		if len(lines) != 2 {
+		if len(lines) != 3 {
 			t.Fatal("unexpected number of lines")
 		}
-		if lines[0] != "antani0... in progress" {
+		if lines[0] != "antani0... started" {
 			t.Fatal("unexpected first line", lines[0])
 		}
-		if lines[1] != "antani0... EOF" {
+		if lines[1] != "antani0... in progress" {
+			t.Fatal("unexpected first line", lines[0])
+		}
+		if lines[2] != "antani0... EOF" {
 			t.Fatal("unexpected first line", lines[0])
 		}
 	})