From 7b6aa6de065196d80891f9498944210a55ef498a Mon Sep 17 00:00:00 2001
From: Simone Basso <bassosimone@gmail.com>
Date: Mon, 9 Oct 2023 13:58:48 +0200
Subject: [PATCH] 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 https://github.com/ooni/probe/issues/2544.
---
 internal/logx/operation.go      |  1 +
 internal/logx/operation_test.go | 32 ++++++++++++++++++++++----------
 2 files changed, 23 insertions(+), 10 deletions(-)

diff --git a/internal/logx/operation.go b/internal/logx/operation.go
index db0ad0b25e..58a1ab439a 100644
--- a/internal/logx/operation.go
+++ b/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
 }
diff --git a/internal/logx/operation_test.go b/internal/logx/operation_test.go
index 2b2321fb88..2f20c96d33 100644
--- a/internal/logx/operation_test.go
+++ b/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])
 		}
 	})