fix(logx): log when an operation is starting (ooni#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])
  }
  })