Add default console logger (#12540)

* Add default console logger

Default console logger writes to stderr.  To enable it, set env var
AZURE_SDK_GO_LOGGING to the value 'all'.
Added Logger.Writef() to reduce the need for ShouldLog() checks.

* convert to lambda

* add LogLongRunningOperation

sdk/azcore/log.go

@@ -5,6 +5,12 @@
 
 package azcore
 
+import (
+	"fmt"
+	"os"
+	"time"
+)
+
 // LogClassification is used to group entries.  Each group can be toggled on or off.
 type LogClassification string
 
@@ -26,6 +32,10 @@ const (
 
 	// LogSlowResponse entries contain information for responses that take longer than the specified threshold.
 	LogSlowResponse LogClassification = "SlowResponse"
+
+	// LogLongRunningOperation entries contain information specific to long-running operations.
+	// This includes information like polling location, operation state and sleep intervals.
+	LogLongRunningOperation LogClassification = "LongRunningOperation"
 )
 
 // Listener is the function signature invoked when writing log entries.
@@ -80,6 +90,15 @@ func (l *Logger) Write(cls LogClassification, message string) {
 	l.lst(cls, message)
 }
 
+// Writef invokes the underlying Listener with the specified classification and formatted message.
+// If the classification shouldn't be logged or there is no listener then Writef does nothing.
+func (l *Logger) Writef(cls LogClassification, format string, a ...interface{}) {
+	if l.lst == nil || !l.Should(cls) {
+		return
+	}
+	l.lst(cls, fmt.Sprintf(format, a...))
+}
+
 // for testing purposes
 func (l *Logger) resetClassifications() {
 	l.cls = nil
@@ -91,3 +110,14 @@ var log Logger
 func Log() *Logger {
 	return &log
 }
+
+func init() {
+	if cls := os.Getenv("AZURE_SDK_GO_LOGGING"); cls == "all" {
+		// cls could be enhanced to support a comma-delimited list of log classifications
+		log.lst = func(cls LogClassification, msg string) {
+			// simple console logger, it writes to stderr in the following format:
+			// [time-stamp] Classification: message
+			fmt.Fprintf(os.Stderr, "[%s] %s: %s\n", time.Now().Format(time.StampMicro), cls, msg)
+		}
+	}
+}

sdk/azcore/log_test.go

@@ -5,7 +5,11 @@
 
 package azcore
 
-import "testing"
+import (
+	"fmt"
+	"net/http"
+	"testing"
+)
 
 func TestLoggingDefault(t *testing.T) {
 	// ensure logging with nil listener doesn't fail
@@ -18,15 +22,15 @@ func TestLoggingDefault(t *testing.T) {
 	})
 	const req = "this is a request"
 	Log().Write(LogRequest, req)
-	const resp = "this is a response"
-	Log().Write(LogResponse, resp)
+	const resp = "this is a response: %d"
+	Log().Writef(LogResponse, resp, http.StatusOK)
 	if l := len(log); l != 2 {
 		t.Fatalf("unexpected log entry count: %d", l)
 	}
 	if log[LogRequest] != req {
 		t.Fatalf("unexpected log request: %s", log[LogRequest])
 	}
-	if log[LogResponse] != resp {
+	if log[LogResponse] != fmt.Sprintf(resp, http.StatusOK) {
 		t.Fatalf("unexpected log response: %s", log[LogResponse])
 	}
 }

sdk/azcore/policy_retry.go

@@ -8,7 +8,6 @@ package azcore
 import (
 	"context"
 	"errors"
-	"fmt"
 	"io"
 	"math/rand"
 	"net/http"
@@ -129,12 +128,9 @@ func (p *retryPolicy) Do(req *Request) (resp *Response, err error) {
 		defer rwbody.realClose()
 	}
 	try := int32(1)
-	shouldLog := Log().Should(LogRetryPolicy)
 	for {
 		resp = nil // reset
-		if shouldLog {
-			Log().Write(LogRetryPolicy, fmt.Sprintf("\n=====> Try=%d\n", try))
-		}
+		Log().Writef(LogRetryPolicy, "\n=====> Try=%d\n", try)
 
 		// For each try, seek to the beginning of the Body stream. We do this even for the 1st try because
 		// the stream may not be at offset 0 when we first get it and we want the same behavior for the
@@ -149,9 +145,7 @@ func (p *retryPolicy) Do(req *Request) (resp *Response, err error) {
 		clone := req.clone(tryCtx)
 		resp, err = clone.Next() // Make the request
 		tryCancel()
-		if shouldLog {
-			Log().Write(LogRetryPolicy, fmt.Sprintf("Err=%v, response=%v\n", err, resp))
-		}
+		Log().Writef(LogRetryPolicy, "Err=%v, response=%v\n", err, resp)
 
 		if err == nil && !resp.HasStatusCode(options.StatusCodes...) {
 			// if there is no error and the response code isn't in the list of retry codes then we're done.
@@ -182,9 +176,7 @@ func (p *retryPolicy) Do(req *Request) (resp *Response, err error) {
 		if delay <= 0 {
 			delay = options.calcDelay(try)
 		}
-		if shouldLog {
-			Log().Write(LogRetryPolicy, fmt.Sprintf("Try=%d, Delay=%v\n", try, delay))
-		}
+		Log().Writef(LogRetryPolicy, "Try=%d, Delay=%v\n", try, delay)
 		select {
 		case <-time.After(delay):
 			try++

sdk/azcore/version.go

@@ -10,5 +10,5 @@ const (
 	UserAgent = "azcore/" + Version
 
 	// Version is the semantic version (see http://semver.org) of the pipeline package.
-	Version = "0.10.0"
+	Version = "0.10.1"
 )