Source file src/cloud.google.com/go/logging/logging_test.go

Documentation: cloud.google.com/go/logging

     1  // Copyright 2016 Google LLC
     2  //
     3  // Licensed under the Apache License, Version 2.0 (the "License");
     4  // you may not use this file except in compliance with the License.
     5  // You may obtain a copy of the License at
     6  //
     7  //      http://www.apache.org/licenses/LICENSE-2.0
     8  //
     9  // Unless required by applicable law or agreed to in writing, software
    10  // distributed under the License is distributed on an "AS IS" BASIS,
    11  // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
    12  // See the License for the specific language governing permissions and
    13  // limitations under the License.
    14  
    15  // TODO(jba): test that OnError is getting called appropriately.
    16  
    17  package logging_test
    18  
    19  import (
    20  	"context"
    21  	"encoding/json"
    22  	"errors"
    23  	"flag"
    24  	"fmt"
    25  	"log"
    26  	"math/rand"
    27  	"net"
    28  	"net/http"
    29  	"net/url"
    30  	"os"
    31  	"path/filepath"
    32  	"reflect"
    33  	"runtime"
    34  	"strings"
    35  	"sync"
    36  	"sync/atomic"
    37  	"testing"
    38  	"time"
    39  
    40  	cinternal "cloud.google.com/go/internal"
    41  	"cloud.google.com/go/internal/testutil"
    42  	"cloud.google.com/go/internal/uid"
    43  	"cloud.google.com/go/logging"
    44  	logpb "cloud.google.com/go/logging/apiv2/loggingpb"
    45  	"cloud.google.com/go/logging/internal"
    46  	ltesting "cloud.google.com/go/logging/internal/testing"
    47  	"cloud.google.com/go/logging/logadmin"
    48  	"github.com/google/go-cmp/cmp"
    49  	"github.com/google/go-cmp/cmp/cmpopts"
    50  	gax "github.com/googleapis/gax-go/v2"
    51  	"golang.org/x/oauth2"
    52  	"google.golang.org/api/iterator"
    53  	"google.golang.org/api/option"
    54  	mrpb "google.golang.org/genproto/googleapis/api/monitoredres"
    55  	"google.golang.org/grpc"
    56  	"google.golang.org/grpc/codes"
    57  	"google.golang.org/grpc/status"
    58  	"google.golang.org/protobuf/types/known/anypb"
    59  )
    60  
    61  const testLogIDPrefix = "GO-LOGGING-CLIENT/TEST-LOG"
    62  
    63  var (
    64  	client        *logging.Client
    65  	aclient       *logadmin.Client
    66  	testProjectID string
    67  	testLogID     string
    68  	testFilter    string
    69  	errorc        chan error
    70  	ctx           context.Context
    71  
    72  	// Adjust the fields of a FullEntry received from the production service
    73  	// before comparing it with the expected result. We can't correctly
    74  	// compare certain fields, like times or server-generated IDs.
    75  	clean func(*logging.Entry)
    76  
    77  	// Create a new client with the given project ID.
    78  	newClients func(ctx context.Context, projectID string) (*logging.Client, *logadmin.Client)
    79  
    80  	uids = uid.NewSpace(testLogIDPrefix, nil)
    81  
    82  	// If true, this test is using the production service, not a fake.
    83  	integrationTest bool
    84  )
    85  
    86  func testNow() time.Time {
    87  	return time.Unix(1000, 0)
    88  }
    89  
    90  func TestMain(m *testing.M) {
    91  	flag.Parse() // needed for testing.Short()
    92  
    93  	// disable ingesting instrumentation log entry
    94  	internal.InstrumentOnce.Do(func() {})
    95  
    96  	ctx = context.Background()
    97  	testProjectID = testutil.ProjID()
    98  	errorc = make(chan error, 100)
    99  	if testProjectID == "" || testing.Short() {
   100  		integrationTest = false
   101  		if testProjectID != "" {
   102  			log.Print("Integration tests skipped in short mode (using fake instead)")
   103  		}
   104  		testProjectID = ltesting.ValidProjectID
   105  		clean = func(e *logging.Entry) {
   106  			// Remove the insert ID for consistency with the integration test.
   107  			e.InsertID = ""
   108  		}
   109  
   110  		addr, err := ltesting.NewServer()
   111  		if err != nil {
   112  			log.Fatalf("creating fake server: %v", err)
   113  		}
   114  		logging.SetNow(testNow)
   115  
   116  		newClients = func(ctx context.Context, parent string) (*logging.Client, *logadmin.Client) {
   117  			conn, err := grpc.Dial(addr, grpc.WithInsecure())
   118  			if err != nil {
   119  				log.Fatalf("dialing %q: %v", addr, err)
   120  			}
   121  			c, err := logging.NewClient(ctx, parent, option.WithGRPCConn(conn))
   122  			if err != nil {
   123  				log.Fatalf("creating client for fake at %q: %v", addr, err)
   124  			}
   125  			ac, err := logadmin.NewClient(ctx, parent, option.WithGRPCConn(conn))
   126  			if err != nil {
   127  				log.Fatalf("creating client for fake at %q: %v", addr, err)
   128  			}
   129  			return c, ac
   130  		}
   131  
   132  	} else {
   133  		integrationTest = true
   134  		clean = func(e *logging.Entry) {
   135  			// We cannot compare timestamps, so set them to the test time.
   136  			// Also, remove the insert ID added by the service.
   137  			e.Timestamp = testNow().UTC()
   138  			e.InsertID = ""
   139  		}
   140  		ts := testutil.TokenSource(ctx, logging.AdminScope)
   141  		if ts == nil {
   142  			log.Fatal("The project key must be set. See CONTRIBUTING.md for details")
   143  		}
   144  		log.Printf("running integration tests with project %s", testProjectID)
   145  		newClients = func(ctx context.Context, parent string) (*logging.Client, *logadmin.Client) {
   146  			c, err := logging.NewClient(ctx, parent, option.WithTokenSource(ts))
   147  			if err != nil {
   148  				log.Fatalf("creating prod client: %v", err)
   149  			}
   150  			ac, err := logadmin.NewClient(ctx, parent, option.WithTokenSource(ts))
   151  			if err != nil {
   152  				log.Fatalf("creating prod client: %v", err)
   153  			}
   154  			return c, ac
   155  		}
   156  
   157  	}
   158  	client, aclient = newClients(ctx, testProjectID)
   159  	client.OnError = func(e error) { errorc <- e }
   160  
   161  	exit := m.Run()
   162  	os.Exit(exit)
   163  }
   164  
   165  func initLogs() {
   166  	testLogID = uids.New()
   167  	hourAgo := time.Now().Add(-1 * time.Hour).UTC()
   168  	testFilter = fmt.Sprintf(`logName = "projects/%s/logs/%s" AND
   169  timestamp >= "%s"`,
   170  		testProjectID, strings.Replace(testLogID, "/", "%2F", -1), hourAgo.Format(time.RFC3339))
   171  }
   172  
   173  func TestLogSync(t *testing.T) {
   174  	initLogs() // Generate new testLogID
   175  	ctx := context.Background()
   176  	lg := client.Logger(testLogID)
   177  	err := lg.LogSync(ctx, logging.Entry{Payload: "hello"})
   178  	if err != nil {
   179  		t.Fatal(err)
   180  	}
   181  	err = lg.LogSync(ctx, logging.Entry{Payload: "goodbye"})
   182  	if err != nil {
   183  		t.Fatal(err)
   184  	}
   185  	// Allow overriding the MonitoredResource.
   186  	err = lg.LogSync(ctx, logging.Entry{Payload: "mr", Resource: &mrpb.MonitoredResource{Type: "global"}})
   187  	if err != nil {
   188  		t.Fatal(err)
   189  	}
   190  
   191  	want := []*logging.Entry{
   192  		entryForTesting("hello"),
   193  		entryForTesting("goodbye"),
   194  		entryForTesting("mr"),
   195  	}
   196  	var got []*logging.Entry
   197  	ok := waitFor(func() bool {
   198  		got, err = allTestLogEntries(ctx)
   199  		if err != nil {
   200  			t.Log("fetching log entries: ", err)
   201  			return false
   202  		}
   203  		return len(got) == len(want)
   204  	})
   205  	if !ok {
   206  		t.Fatalf("timed out; got: %d, want: %d\n", len(got), len(want))
   207  	}
   208  	if msg, ok := compareEntries(got, want); !ok {
   209  		t.Error(msg)
   210  	}
   211  }
   212  
   213  func TestLogAndEntries(t *testing.T) {
   214  	initLogs() // Generate new testLogID
   215  	ctx := context.Background()
   216  	payloads := []string{"p1", "p2", "p3", "p4", "p5"}
   217  	lg := client.Logger(testLogID)
   218  	for _, p := range payloads {
   219  		// Use the insert ID to guarantee iteration order.
   220  		lg.Log(logging.Entry{Payload: p, InsertID: p})
   221  	}
   222  	if err := lg.Flush(); err != nil {
   223  		t.Fatal(err)
   224  	}
   225  	var want []*logging.Entry
   226  	for _, p := range payloads {
   227  		want = append(want, entryForTesting(p))
   228  	}
   229  	var got []*logging.Entry
   230  	ok := waitFor(func() bool {
   231  		var err error
   232  		got, err = allTestLogEntries(ctx)
   233  		if err != nil {
   234  			t.Log("fetching log entries: ", err)
   235  			return false
   236  		}
   237  		return len(got) == len(want)
   238  	})
   239  	if !ok {
   240  		t.Fatalf("timed out; got: %d, want: %d\n", len(got), len(want))
   241  	}
   242  	if msg, ok := compareEntries(got, want); !ok {
   243  		t.Error(msg)
   244  	}
   245  }
   246  
   247  func TestLogInvalidUtf8(t *testing.T) {
   248  	lg := client.Logger(testLogID)
   249  	msg := fmt.Sprintf("\x6c\x6f\x67\xe5")
   250  	lg.Log(logging.Entry{
   251  		Payload:   msg,
   252  		Timestamp: time.Now(),
   253  	})
   254  	err := lg.Flush()
   255  	s, _ := status.FromError(err)
   256  	if !strings.Contains(s.Message(), "string field contains invalid UTF-8") {
   257  		t.Fatalf("got an incorrect error: %v", err)
   258  	}
   259  }
   260  
   261  func TestContextFunc(t *testing.T) {
   262  	initLogs()
   263  	var contextFuncCalls, cleanupCalls int32 //atomic
   264  
   265  	lg := client.Logger(testLogID, logging.ContextFunc(func() (context.Context, func()) {
   266  		atomic.AddInt32(&contextFuncCalls, 1)
   267  		return context.Background(), func() { atomic.AddInt32(&cleanupCalls, 1) }
   268  	}))
   269  	lg.Log(logging.Entry{Payload: "p"})
   270  	if err := lg.Flush(); err != nil {
   271  		t.Fatal(err)
   272  	}
   273  	got1 := atomic.LoadInt32(&contextFuncCalls)
   274  	got2 := atomic.LoadInt32(&cleanupCalls)
   275  	if got1 != 1 || got1 != got2 {
   276  		t.Errorf("got %d calls to context func, %d calls to cleanup func; want 1, 1", got1, got2)
   277  	}
   278  }
   279  
   280  func TestToLogEntry(t *testing.T) {
   281  	u := &url.URL{Scheme: "http"}
   282  	tests := []struct {
   283  		name      string
   284  		in        logging.Entry
   285  		want      *logpb.LogEntry
   286  		wantError error
   287  	}{
   288  		{
   289  			name: "BlankLogEntry",
   290  			in:   logging.Entry{},
   291  			want: &logpb.LogEntry{},
   292  		}, {
   293  			name: "Already set Trace",
   294  			in:   logging.Entry{Trace: "t1"},
   295  			want: &logpb.LogEntry{Trace: "t1"},
   296  		}, {
   297  			name: "No X-Trace-Context header",
   298  			in: logging.Entry{
   299  				HTTPRequest: &logging.HTTPRequest{
   300  					Request: &http.Request{URL: u, Header: http.Header{"foo": {"bar"}}},
   301  				},
   302  			},
   303  			want: &logpb.LogEntry{},
   304  		}, {
   305  			name: "X-Trace-Context header with all fields",
   306  			in: logging.Entry{
   307  				TraceSampled: false,
   308  				HTTPRequest: &logging.HTTPRequest{
   309  					Request: &http.Request{
   310  						URL:    u,
   311  						Header: http.Header{"X-Cloud-Trace-Context": {"105445aa7843bc8bf206b120001000/000000000000004a;o=1"}},
   312  					},
   313  				},
   314  			},
   315  			want: &logpb.LogEntry{
   316  				Trace:        "projects/P/traces/105445aa7843bc8bf206b120001000",
   317  				SpanId:       "000000000000004a",
   318  				TraceSampled: true,
   319  			},
   320  		}, {
   321  			name: "X-Trace-Context header with all fields; TraceSampled explicitly set",
   322  			in: logging.Entry{
   323  				TraceSampled: true,
   324  				HTTPRequest: &logging.HTTPRequest{
   325  					Request: &http.Request{
   326  						URL:    u,
   327  						Header: http.Header{"X-Cloud-Trace-Context": {"105445aa7843bc8bf206b120001000/000000000000004a;o=0"}},
   328  					},
   329  				},
   330  			},
   331  			want: &logpb.LogEntry{
   332  				Trace:        "projects/P/traces/105445aa7843bc8bf206b120001000",
   333  				SpanId:       "000000000000004a",
   334  				TraceSampled: true,
   335  			},
   336  		}, {
   337  			name: "X-Trace-Context header with all fields; TraceSampled from Header",
   338  			in: logging.Entry{
   339  				HTTPRequest: &logging.HTTPRequest{
   340  					Request: &http.Request{
   341  						URL:    u,
   342  						Header: http.Header{"X-Cloud-Trace-Context": {"105445aa7843bc8bf206b120001000/000000000000004a;o=1"}},
   343  					},
   344  				},
   345  			},
   346  			want: &logpb.LogEntry{
   347  				Trace:        "projects/P/traces/105445aa7843bc8bf206b120001000",
   348  				SpanId:       "000000000000004a",
   349  				TraceSampled: true,
   350  			},
   351  		}, {
   352  			name: "X-Trace-Context header with blank trace",
   353  			in: logging.Entry{
   354  				HTTPRequest: &logging.HTTPRequest{
   355  					Request: &http.Request{
   356  						URL:    u,
   357  						Header: http.Header{"X-Cloud-Trace-Context": {"/0;o=1"}},
   358  					},
   359  				},
   360  			},
   361  			want: &logpb.LogEntry{},
   362  		}, {
   363  			name: "X-Trace-Context header with blank span",
   364  			in: logging.Entry{
   365  				HTTPRequest: &logging.HTTPRequest{
   366  					Request: &http.Request{
   367  						URL:    u,
   368  						Header: http.Header{"X-Cloud-Trace-Context": {"105445aa7843bc8bf206b120001000/;o=0"}},
   369  					},
   370  				},
   371  			},
   372  			want: &logpb.LogEntry{
   373  				Trace: "projects/P/traces/105445aa7843bc8bf206b120001000",
   374  			},
   375  		}, {
   376  			name: "X-Trace-Context header with missing traceSampled aka ?o=*",
   377  			in: logging.Entry{
   378  				HTTPRequest: &logging.HTTPRequest{
   379  					Request: &http.Request{
   380  						URL:    u,
   381  						Header: http.Header{"X-Cloud-Trace-Context": {"105445aa7843bc8bf206b120001000/0"}},
   382  					},
   383  				},
   384  			},
   385  			want: &logpb.LogEntry{
   386  				Trace: "projects/P/traces/105445aa7843bc8bf206b120001000",
   387  			},
   388  		}, {
   389  			name: "X-Trace-Context header with all blank fields",
   390  			in: logging.Entry{
   391  				HTTPRequest: &logging.HTTPRequest{
   392  					Request: &http.Request{
   393  						URL:    u,
   394  						Header: http.Header{"X-Cloud-Trace-Context": {""}},
   395  					},
   396  				},
   397  			},
   398  			want: &logpb.LogEntry{},
   399  		}, {
   400  			name: "Invalid X-Trace-Context header but already set TraceID",
   401  			in: logging.Entry{
   402  				HTTPRequest: &logging.HTTPRequest{
   403  					Request: &http.Request{
   404  						URL:    u,
   405  						Header: http.Header{"X-Cloud-Trace-Context": {"t3"}},
   406  					},
   407  				},
   408  				Trace: "t4",
   409  			},
   410  			want: &logpb.LogEntry{
   411  				Trace: "t4",
   412  			},
   413  		}, {
   414  			name: "Already set TraceID and SpanID",
   415  			in:   logging.Entry{Trace: "t1", SpanID: "007"},
   416  			want: &logpb.LogEntry{
   417  				Trace:  "t1",
   418  				SpanId: "007",
   419  			},
   420  		}, {
   421  			name: "Empty request produces an error",
   422  			in: logging.Entry{
   423  				HTTPRequest: &logging.HTTPRequest{
   424  					RequestSize: 128,
   425  				},
   426  			},
   427  			wantError: errors.New("logging: HTTPRequest must have a non-nil Request"),
   428  		},
   429  		{
   430  			name: "Traceparent header with entry fields unset",
   431  			in: logging.Entry{
   432  				HTTPRequest: &logging.HTTPRequest{
   433  					Request: &http.Request{
   434  						URL:    u,
   435  						Header: http.Header{"Traceparent": {"00-105445aa7843bc8bf206b12000100012-000000000000004a-01"}},
   436  					},
   437  				},
   438  			},
   439  			want: &logpb.LogEntry{
   440  				Trace:  "projects/P/traces/105445aa7843bc8bf206b12000100012",
   441  				SpanId: "000000000000004a",
   442  			},
   443  		},
   444  		{
   445  			name: "traceparent header with preset sampled field",
   446  			in: logging.Entry{
   447  				TraceSampled: true,
   448  				HTTPRequest: &logging.HTTPRequest{
   449  					Request: &http.Request{
   450  						URL:    u,
   451  						Header: http.Header{"Traceparent": {"00-105445aa7843bc8bf206b12000100012-000000000000004a-00"}},
   452  					},
   453  				},
   454  			},
   455  			want: &logpb.LogEntry{
   456  				Trace:        "projects/P/traces/105445aa7843bc8bf206b12000100012",
   457  				SpanId:       "000000000000004a",
   458  				TraceSampled: true,
   459  			},
   460  		},
   461  		{
   462  			name: "Traceparent header together with x-trace-context header",
   463  			in: logging.Entry{
   464  				HTTPRequest: &logging.HTTPRequest{
   465  					Request: &http.Request{
   466  						URL: u,
   467  						Header: http.Header{
   468  							"X-Cloud-Trace-Context": {"105445aa7843bc8bf206b120000000/0000000000000bbb;o=1"},
   469  							"Traceparent":           {"00-105445aa7843bc8bf206b1200010aaaa-0000000000000aaa-00"}},
   470  					},
   471  				},
   472  			},
   473  			want: &logpb.LogEntry{
   474  				Trace:  "projects/P/traces/105445aa7843bc8bf206b1200010aaaa",
   475  				SpanId: "0000000000000aaa",
   476  			},
   477  		},
   478  		{
   479  			name: "Traceparent header invalid protocol",
   480  			in: logging.Entry{
   481  				HTTPRequest: &logging.HTTPRequest{
   482  					Request: &http.Request{
   483  						URL:    u,
   484  						Header: http.Header{"Traceparent": {"01-105445aa7843bc8bf206b12000100012-000000000000004a-00"}},
   485  					},
   486  				},
   487  			},
   488  			want: &logpb.LogEntry{},
   489  		},
   490  		{
   491  			name: "Traceparent header short trace field",
   492  			in: logging.Entry{
   493  				HTTPRequest: &logging.HTTPRequest{
   494  					Request: &http.Request{
   495  						URL:    u,
   496  						Header: http.Header{"Traceparent": {"00-12345678901234567890-000000000000004a-00"}},
   497  					},
   498  				},
   499  			},
   500  			want: &logpb.LogEntry{},
   501  		},
   502  		{
   503  			name: "Traceparent header long trace field",
   504  			in: logging.Entry{
   505  				HTTPRequest: &logging.HTTPRequest{
   506  					Request: &http.Request{
   507  						URL:    u,
   508  						Header: http.Header{"Traceparent": {"00-1234567890123456789012345678901234567890-000000000000004a-00"}},
   509  					},
   510  				},
   511  			},
   512  			want: &logpb.LogEntry{},
   513  		},
   514  		{
   515  			name: "Traceparent header invalid trace field",
   516  			in: logging.Entry{
   517  				HTTPRequest: &logging.HTTPRequest{
   518  					Request: &http.Request{
   519  						URL:    u,
   520  						Header: http.Header{"Traceparent": {"00-123456789012345678901234567890xx-000000000000004a-00"}},
   521  					},
   522  				},
   523  			},
   524  			want: &logpb.LogEntry{},
   525  		},
   526  		{
   527  			name: "Traceparent header trace field all 0s",
   528  			in: logging.Entry{
   529  				HTTPRequest: &logging.HTTPRequest{
   530  					Request: &http.Request{
   531  						URL:    u,
   532  						Header: http.Header{"Traceparent": {"00-00000000000000000000000000000000-000000000000004a-00"}},
   533  					},
   534  				},
   535  			},
   536  			want: &logpb.LogEntry{},
   537  		},
   538  		{
   539  			name: "Traceparent header short span field",
   540  			in: logging.Entry{
   541  				HTTPRequest: &logging.HTTPRequest{
   542  					Request: &http.Request{
   543  						URL:    u,
   544  						Header: http.Header{"Traceparent": {"00-12345678901234567890123456789012-123456789012345-00"}},
   545  					},
   546  				},
   547  			},
   548  			want: &logpb.LogEntry{},
   549  		},
   550  		{
   551  			name: "Traceparent header long span field",
   552  			in: logging.Entry{
   553  				HTTPRequest: &logging.HTTPRequest{
   554  					Request: &http.Request{
   555  						URL:    u,
   556  						Header: http.Header{"Traceparent": {"00-12345678901234567890123456789012-12345678901234567890-00"}},
   557  					},
   558  				},
   559  			},
   560  			want: &logpb.LogEntry{},
   561  		},
   562  		{
   563  			name: "Traceparent header invalid span field",
   564  			in: logging.Entry{
   565  				HTTPRequest: &logging.HTTPRequest{
   566  					Request: &http.Request{
   567  						URL:    u,
   568  						Header: http.Header{"Traceparent": {"00-12345678901234567890123456789012-abcdefghijklmnop-00"}},
   569  					},
   570  				},
   571  			},
   572  			want: &logpb.LogEntry{},
   573  		},
   574  		{
   575  			name: "Traceparent header span field all 0s",
   576  			in: logging.Entry{
   577  				HTTPRequest: &logging.HTTPRequest{
   578  					Request: &http.Request{
   579  						URL:    u,
   580  						Header: http.Header{"Traceparent": {"00-12345678901234567890123456789012-0000000000000000-00"}},
   581  					},
   582  				},
   583  			},
   584  			want: &logpb.LogEntry{},
   585  		},
   586  	}
   587  	for _, test := range tests {
   588  		t.Run(test.name, func(t *testing.T) {
   589  			e, err := logging.ToLogEntry(test.in, "projects/P")
   590  			if err != nil && test.wantError == nil {
   591  				t.Fatalf("Unexpected error: %+v: %v", test.in, err)
   592  			}
   593  			if err == nil && test.wantError != nil {
   594  				t.Fatalf("Error is expected: %+v: %v", test.in, test.wantError)
   595  			}
   596  			if test.wantError != nil {
   597  				return
   598  			}
   599  			if got := e.Trace; got != test.want.Trace {
   600  				t.Errorf("TraceId: %+v: got %q, want %q", test.in, got, test.want.Trace)
   601  			}
   602  			if got := e.SpanId; got != test.want.SpanId {
   603  				t.Errorf("SpanId: %+v: got %q, want %q", test.in, got, test.want.SpanId)
   604  			}
   605  			if got := e.TraceSampled; got != test.want.TraceSampled {
   606  				t.Errorf("TraceSampled: %+v: got %t, want %t", test.in, got, test.want.TraceSampled)
   607  			}
   608  		})
   609  	}
   610  }
   611  
   612  // compareEntries compares most fields list of Entries against expected. compareEntries does not compare:
   613  //   - HTTPRequest
   614  //   - Operation
   615  //   - Resource
   616  //   - SourceLocation
   617  func compareEntries(got, want []*logging.Entry) (string, bool) {
   618  	if len(got) != len(want) {
   619  		return fmt.Sprintf("got %d entries, want %d", len(got), len(want)), false
   620  	}
   621  	for i := range got {
   622  		if !compareEntry(got[i], want[i]) {
   623  			return fmt.Sprintf("#%d:\ngot  %+v\nwant %+v", i, got[i], want[i]), false
   624  		}
   625  	}
   626  	return "", true
   627  }
   628  
   629  func compareEntry(got, want *logging.Entry) bool {
   630  	if got.Timestamp.Unix() != want.Timestamp.Unix() {
   631  		return false
   632  	}
   633  
   634  	if got.Severity != want.Severity {
   635  		return false
   636  	}
   637  
   638  	if !ltesting.PayloadEqual(got.Payload, want.Payload) {
   639  		return false
   640  	}
   641  	if !testutil.Equal(got.Labels, want.Labels) {
   642  		return false
   643  	}
   644  
   645  	if got.InsertID != want.InsertID {
   646  		return false
   647  	}
   648  
   649  	if got.LogName != want.LogName {
   650  		return false
   651  	}
   652  
   653  	return true
   654  }
   655  
   656  func entryForTesting(payload interface{}) *logging.Entry {
   657  	return &logging.Entry{
   658  		Timestamp: testNow().UTC(),
   659  		Payload:   payload,
   660  		LogName:   "projects/" + testProjectID + "/logs/" + testLogID,
   661  		Resource:  &mrpb.MonitoredResource{Type: "global", Labels: map[string]string{"project_id": testProjectID}},
   662  	}
   663  }
   664  
   665  // allTestLogEntries should be called sparingly. It takes ~10s to get logs, even with indexed filters.
   666  func allTestLogEntries(ctx context.Context) ([]*logging.Entry, error) {
   667  	return allEntries(ctx, aclient, testFilter)
   668  }
   669  
   670  func allEntries(ctx context.Context, aclient *logadmin.Client, filter string) ([]*logging.Entry, error) {
   671  	var es []*logging.Entry
   672  	it := aclient.Entries(ctx, logadmin.Filter(filter))
   673  	for {
   674  		e, err := cleanNext(it)
   675  		switch err {
   676  		case nil:
   677  			es = append(es, e)
   678  		case iterator.Done:
   679  			return es, nil
   680  		default:
   681  			return nil, err
   682  		}
   683  	}
   684  }
   685  
   686  func cleanNext(it *logadmin.EntryIterator) (*logging.Entry, error) {
   687  	e, err := it.Next()
   688  	if err != nil {
   689  		return nil, err
   690  	}
   691  	clean(e)
   692  	return e, nil
   693  }
   694  
   695  func TestStandardLogger(t *testing.T) {
   696  	initLogs() // Generate new testLogID
   697  	ctx := context.Background()
   698  	lg := client.Logger(testLogID)
   699  	slg := lg.StandardLogger(logging.Info)
   700  
   701  	if slg != lg.StandardLogger(logging.Info) {
   702  		t.Error("There should be only one standard logger at each severity.")
   703  	}
   704  	if slg == lg.StandardLogger(logging.Debug) {
   705  		t.Error("There should be a different standard logger for each severity.")
   706  	}
   707  
   708  	slg.Print("info")
   709  	if err := lg.Flush(); err != nil {
   710  		t.Fatal(err)
   711  	}
   712  	var got []*logging.Entry
   713  	ok := waitFor(func() bool {
   714  		var err error
   715  		got, err = allTestLogEntries(ctx)
   716  		if err != nil {
   717  			t.Log("fetching log entries: ", err)
   718  			return false
   719  		}
   720  		return len(got) == 1
   721  	})
   722  	if !ok {
   723  		t.Fatalf("timed out; got: %d, want: %d\n", len(got), 1)
   724  	}
   725  	if len(got) != 1 {
   726  		t.Fatalf("expected non-nil request with one entry; got:\n%+v", got)
   727  	}
   728  	if got, want := got[0].Payload.(string), "info\n"; got != want {
   729  		t.Errorf("payload: got %q, want %q", got, want)
   730  	}
   731  	if got, want := logging.Severity(got[0].Severity), logging.Info; got != want {
   732  		t.Errorf("severity: got %s, want %s", got, want)
   733  	}
   734  }
   735  
   736  func TestStandardLoggerPopulateSourceLocation(t *testing.T) {
   737  	initLogs() // Generate new testLogID
   738  	ctx := context.Background()
   739  	lg := client.Logger(testLogID, logging.SourceLocationPopulation(logging.AlwaysPopulateSourceLocation))
   740  	slg := lg.StandardLogger(logging.Info)
   741  
   742  	_, _, line, lineOk := runtime.Caller(0)
   743  	if !lineOk {
   744  		t.Fatal("Cannot determine line number")
   745  	}
   746  	wantLine := int64(line + 5)
   747  	slg.Print("info")
   748  	if err := lg.Flush(); err != nil {
   749  		t.Fatal(err)
   750  	}
   751  	var got []*logging.Entry
   752  	ok := waitFor(func() bool {
   753  		var err error
   754  		got, err = allTestLogEntries(ctx)
   755  		if err != nil {
   756  			t.Log("fetching log entries: ", err)
   757  			return false
   758  		}
   759  		return len(got) == 1
   760  	})
   761  	if !ok {
   762  		t.Fatalf("timed out; got: %d, want: %d\n", len(got), 1)
   763  	}
   764  	if len(got) != 1 {
   765  		t.Fatalf("expected non-nil request with one entry; got:\n%+v", got)
   766  	}
   767  	if got, want := filepath.Base(got[0].SourceLocation.GetFile()), "logging_test.go"; got != want {
   768  		t.Errorf("sourcelocation file: got %s, want %s", got, want)
   769  	}
   770  	if got, want := got[0].SourceLocation.GetFunction(), "cloud.google.com/go/logging_test.TestStandardLoggerPopulateSourceLocation"; got != want {
   771  		t.Errorf("sourcelocation function: got %s, want %s", got, want)
   772  	}
   773  	if got := got[0].SourceLocation.Line; got != wantLine {
   774  		t.Errorf("source location line: got %d, want %d", got, wantLine)
   775  	}
   776  }
   777  
   778  func TestStandardLoggerFromTemplate(t *testing.T) {
   779  	tests := []struct {
   780  		name     string
   781  		template logging.Entry
   782  		message  string
   783  		want     logging.Entry
   784  	}{
   785  		{
   786  			name: "severity only",
   787  			template: logging.Entry{
   788  				Severity: logging.Error,
   789  			},
   790  			message: "log message",
   791  			want: logging.Entry{
   792  				Severity: logging.Error,
   793  				Payload:  "log message\n",
   794  			},
   795  		},
   796  		{
   797  			name: "severity and trace",
   798  			template: logging.Entry{
   799  				Severity: logging.Info,
   800  				Trace:    "projects/P/traces/105445aa7843bc8bf206b120001000",
   801  			},
   802  			message: "log message",
   803  			want: logging.Entry{
   804  				Severity: logging.Info,
   805  				Payload:  "log message\n",
   806  				Trace:    "projects/P/traces/105445aa7843bc8bf206b120001000",
   807  			},
   808  		},
   809  		{
   810  			name: "severity and http request",
   811  			template: logging.Entry{
   812  				Severity: logging.Info,
   813  				HTTPRequest: &logging.HTTPRequest{
   814  					Request: &http.Request{
   815  						Method: "GET",
   816  						Host:   "example.com",
   817  					},
   818  					Status: 200,
   819  				},
   820  			},
   821  			message: "log message",
   822  			want: logging.Entry{
   823  				Severity: logging.Info,
   824  				Payload:  "log message\n",
   825  				HTTPRequest: &logging.HTTPRequest{
   826  					Request: &http.Request{
   827  						Method: "GET",
   828  						Host:   "example.com",
   829  					},
   830  					Status: 200,
   831  				},
   832  			},
   833  		},
   834  		{
   835  			name: "payload in template is ignored",
   836  			template: logging.Entry{
   837  				Severity: logging.Info,
   838  				Payload:  "this should not be set in the template",
   839  				Trace:    "projects/P/traces/105445aa7843bc8bf206b120001000",
   840  			},
   841  			message: "log message",
   842  			want: logging.Entry{
   843  				Severity: logging.Info,
   844  				Payload:  "log message\n",
   845  				Trace:    "projects/P/traces/105445aa7843bc8bf206b120001000",
   846  			},
   847  		},
   848  	}
   849  	lg := client.Logger(testLogID)
   850  	for _, tc := range tests {
   851  		t.Run(tc.name, func(t *testing.T) {
   852  			mock := func(got logging.Entry, l *logging.Logger, parent string, skipLevels int) (*logpb.LogEntry, error) {
   853  				if !reflect.DeepEqual(got, tc.want) {
   854  					t.Errorf("Emitted Entry incorrect. Expected %v got %v", tc.want, got)
   855  				}
   856  				// Return value is not interesting
   857  				return &logpb.LogEntry{}, nil
   858  			}
   859  
   860  			f := logging.SetToLogEntryInternal(mock)
   861  			defer func() { logging.SetToLogEntryInternal(f) }()
   862  
   863  			slg := lg.StandardLoggerFromTemplate(&tc.template)
   864  			slg.Print(tc.message)
   865  			if err := lg.Flush(); err != nil {
   866  				t.Fatal(err)
   867  			}
   868  		})
   869  	}
   870  }
   871  
   872  func TestSeverity(t *testing.T) {
   873  	if got, want := logging.Info.String(), "Info"; got != want {
   874  		t.Errorf("got %q, want %q", got, want)
   875  	}
   876  	if got, want := logging.Severity(-99).String(), "-99"; got != want {
   877  		t.Errorf("got %q, want %q", got, want)
   878  	}
   879  }
   880  
   881  func TestParseSeverity(t *testing.T) {
   882  	for _, test := range []struct {
   883  		in   string
   884  		want logging.Severity
   885  	}{
   886  		{"", logging.Default},
   887  		{"whatever", logging.Default},
   888  		{"Default", logging.Default},
   889  		{"ERROR", logging.Error},
   890  		{"Error", logging.Error},
   891  		{"error", logging.Error},
   892  	} {
   893  		got := logging.ParseSeverity(test.in)
   894  		if got != test.want {
   895  			t.Errorf("%q: got %s, want %s\n", test.in, got, test.want)
   896  		}
   897  	}
   898  }
   899  
   900  func TestErrors(t *testing.T) {
   901  	initLogs() // Generate new testLogID
   902  	// Drain errors already seen.
   903  loop:
   904  	for {
   905  		select {
   906  		case <-errorc:
   907  		default:
   908  			break loop
   909  		}
   910  	}
   911  	// Try to log something that can't be JSON-marshalled.
   912  	lg := client.Logger(testLogID)
   913  	lg.Log(logging.Entry{Payload: func() {}})
   914  	// Expect an error from Flush.
   915  	err := lg.Flush()
   916  	if err == nil {
   917  		t.Fatal("expected error, got nil")
   918  	}
   919  }
   920  
   921  type badTokenSource struct{}
   922  
   923  func (badTokenSource) Token() (*oauth2.Token, error) {
   924  	return &oauth2.Token{}, nil
   925  }
   926  
   927  func TestPing(t *testing.T) {
   928  	// Ping twice, in case the service's InsertID logic messes with the error code.
   929  	ctx := context.Background()
   930  	// The global client should be valid.
   931  	if err := client.Ping(ctx); err != nil {
   932  		t.Errorf("project %s: got %v, expected nil", testProjectID, err)
   933  	}
   934  	if err := client.Ping(ctx); err != nil {
   935  		t.Errorf("project %s, #2: got %v, expected nil", testProjectID, err)
   936  	}
   937  	// nonexistent project
   938  	c, a := newClients(ctx, testProjectID+"-BAD")
   939  	defer c.Close()
   940  	defer a.Close()
   941  	if err := c.Ping(ctx); err == nil {
   942  		t.Errorf("nonexistent project: want error pinging logging api, got nil")
   943  	}
   944  	if err := c.Ping(ctx); err == nil {
   945  		t.Errorf("nonexistent project, #2: want error pinging logging api, got nil")
   946  	}
   947  
   948  	// Bad creds. We cannot test this with the fake, since it doesn't do auth.
   949  	if integrationTest {
   950  		c, err := logging.NewClient(ctx, testProjectID, option.WithTokenSource(badTokenSource{}))
   951  		if err != nil {
   952  			t.Fatal(err)
   953  		}
   954  		if err := c.Ping(ctx); err == nil {
   955  			t.Errorf("bad creds: want error pinging logging api, got nil")
   956  		}
   957  		if err := c.Ping(ctx); err == nil {
   958  			t.Errorf("bad creds, #2: want error pinging logging api, got nil")
   959  		}
   960  		if err := c.Close(); err != nil {
   961  			t.Fatalf("error closing client: %v", err)
   962  		}
   963  	}
   964  }
   965  
   966  func TestDeleteLog(t *testing.T) {
   967  	ctx := context.Background()
   968  	initLogs()
   969  	c, a := newClients(ctx, testProjectID)
   970  	defer c.Close()
   971  	defer a.Close()
   972  	lg := c.Logger(testLogID)
   973  
   974  	if err := lg.LogSync(ctx, logging.Entry{Payload: "hello"}); err != nil {
   975  		t.Fatal(err)
   976  	}
   977  
   978  	if err := aclient.DeleteLog(ctx, testLogID); err != nil {
   979  		// Ignore NotFound. Sometimes, amazingly, DeleteLog cannot find
   980  		// a log that is returned by Logs.
   981  		if status.Code(err) != codes.NotFound {
   982  			t.Fatalf("deleting %q: %v", testLogID, err)
   983  		}
   984  	} else {
   985  		t.Logf("deleted log_id: %q", testLogID)
   986  	}
   987  }
   988  
   989  func TestNonProjectParent(t *testing.T) {
   990  	ctx := context.Background()
   991  	initLogs()
   992  	parent := "organizations/" + ltesting.ValidOrgID
   993  	c, a := newClients(ctx, parent)
   994  	defer c.Close()
   995  	defer a.Close()
   996  	lg := c.Logger(testLogID)
   997  	err := lg.LogSync(ctx, logging.Entry{Payload: "hello"})
   998  	if integrationTest {
   999  		// We don't have permission to log to the organization.
  1000  		if got, want := status.Code(err), codes.PermissionDenied; got != want {
  1001  			t.Errorf("got code %s, want %s", got, want)
  1002  		}
  1003  		return
  1004  	}
  1005  	// Continue test against fake.
  1006  	if err != nil {
  1007  		t.Fatal(err)
  1008  	}
  1009  	want := []*logging.Entry{{
  1010  		Timestamp: testNow().UTC(),
  1011  		Payload:   "hello",
  1012  		LogName:   parent + "/logs/" + testLogID,
  1013  		Resource: &mrpb.MonitoredResource{
  1014  			Type:   "organization",
  1015  			Labels: map[string]string{"organization_id": ltesting.ValidOrgID},
  1016  		},
  1017  	}}
  1018  	var got []*logging.Entry
  1019  	ok := waitFor(func() bool {
  1020  		got, err = allEntries(ctx, a, fmt.Sprintf(`logName = "%s/logs/%s"`, parent,
  1021  			strings.Replace(testLogID, "/", "%2F", -1)))
  1022  		if err != nil {
  1023  			t.Log("fetching log entries: ", err)
  1024  			return false
  1025  		}
  1026  		return len(got) == len(want)
  1027  	})
  1028  	if !ok {
  1029  		t.Fatalf("timed out; got: %d, want: %d\n", len(got), len(want))
  1030  	}
  1031  	if msg, ok := compareEntries(got, want); !ok {
  1032  		t.Error(msg)
  1033  	}
  1034  }
  1035  
  1036  func TestDetectProjectIdParent(t *testing.T) {
  1037  	ctx := context.Background()
  1038  	initLogs()
  1039  	addr, err := ltesting.NewServer()
  1040  	if err != nil {
  1041  		t.Fatalf("creating fake server: %v", err)
  1042  	}
  1043  	conn, err := grpc.Dial(addr, grpc.WithInsecure())
  1044  	if err != nil {
  1045  		t.Fatalf("dialing %q: %v", addr, err)
  1046  	}
  1047  
  1048  	tests := []struct {
  1049  		name      string
  1050  		resource  *mrpb.MonitoredResource
  1051  		want      string
  1052  		wantError error
  1053  	}{
  1054  		{
  1055  			name: "Test DetectProjectId parent properly set up resource detection",
  1056  			resource: &mrpb.MonitoredResource{
  1057  				Labels: map[string]string{"project_id": testProjectID},
  1058  			},
  1059  			want: "projects/" + testProjectID,
  1060  		},
  1061  		{
  1062  			name:      "Test DetectProjectId parent no resource detected",
  1063  			resource:  nil,
  1064  			wantError: errors.New("could not determine project ID from environment"),
  1065  		},
  1066  	}
  1067  
  1068  	for _, test := range tests {
  1069  		t.Run(test.name, func(t *testing.T) {
  1070  			// Check if toLogEntryInternal was called with the right parent
  1071  			toLogEntryInternalMock := func(got logging.Entry, l *logging.Logger, parent string, skipLevels int) (*logpb.LogEntry, error) {
  1072  				if parent != test.want {
  1073  					t.Errorf("toLogEntryInternal called with wrong parent. got: %s want: %s", parent, test.want)
  1074  				}
  1075  				return &logpb.LogEntry{}, nil
  1076  			}
  1077  
  1078  			detectResourceMock := func() *mrpb.MonitoredResource {
  1079  				return test.resource
  1080  			}
  1081  
  1082  			realToLogEntryInternal := logging.SetToLogEntryInternal(toLogEntryInternalMock)
  1083  			defer func() { logging.SetToLogEntryInternal(realToLogEntryInternal) }()
  1084  
  1085  			realDetectResourceInternal := logging.SetDetectResourceInternal(detectResourceMock)
  1086  			defer func() { logging.SetDetectResourceInternal(realDetectResourceInternal) }()
  1087  
  1088  			cli, err := logging.NewClient(ctx, logging.DetectProjectID, option.WithGRPCConn(conn))
  1089  			if err != nil && test.wantError == nil {
  1090  				t.Fatalf("Unexpected error: %+v: %v", test.resource, err)
  1091  			}
  1092  			if err == nil && test.wantError != nil {
  1093  				t.Fatalf("Error is expected: %+v: %v", test.resource, test.wantError)
  1094  			}
  1095  			if test.wantError != nil {
  1096  				return
  1097  			}
  1098  
  1099  			cli.Logger(testLogID).LogSync(ctx, logging.Entry{Payload: "hello"})
  1100  		})
  1101  	}
  1102  }
  1103  
  1104  // waitFor calls f repeatedly with exponential backoff, blocking until it returns true.
  1105  // It returns false after a while (if it times out).
  1106  func waitFor(f func() bool) bool {
  1107  	// TODO(shadams): Find a better way to deflake these tests.
  1108  	ctx, cancel := context.WithTimeout(context.Background(), 10*time.Minute)
  1109  	defer cancel()
  1110  	err := cinternal.Retry(ctx,
  1111  		gax.Backoff{Initial: time.Second, Multiplier: 2, Max: 30 * time.Second},
  1112  		func() (bool, error) { return f(), nil })
  1113  	return err == nil
  1114  }
  1115  
  1116  // Interleave a lot of Log and Flush calls, to induce race conditions.
  1117  // Run this test with:
  1118  //
  1119  //	go test -run LogFlushRace -race -count 100
  1120  func TestLogFlushRace(t *testing.T) {
  1121  	initLogs() // Generate new testLogID
  1122  	lg := client.Logger(testLogID,
  1123  		logging.ConcurrentWriteLimit(5),  // up to 5 concurrent log writes
  1124  		logging.EntryCountThreshold(100)) // small bundle size to increase interleaving
  1125  	var wgf, wgl sync.WaitGroup
  1126  	donec := make(chan struct{})
  1127  	for i := 0; i < 10; i++ {
  1128  		wgl.Add(1)
  1129  		go func() {
  1130  			defer wgl.Done()
  1131  			for j := 0; j < 1e4; j++ {
  1132  				lg.Log(logging.Entry{Payload: "the payload"})
  1133  			}
  1134  		}()
  1135  	}
  1136  	for i := 0; i < 5; i++ {
  1137  		wgf.Add(1)
  1138  		go func() {
  1139  			defer wgf.Done()
  1140  			for {
  1141  				select {
  1142  				case <-donec:
  1143  					return
  1144  				case <-time.After(time.Duration(rand.Intn(5)) * time.Millisecond):
  1145  					if err := lg.Flush(); err != nil {
  1146  						t.Error(err)
  1147  					}
  1148  				}
  1149  			}
  1150  		}()
  1151  	}
  1152  	wgl.Wait()
  1153  	close(donec)
  1154  	wgf.Wait()
  1155  }
  1156  
  1157  // Test the throughput of concurrent writers.
  1158  func BenchmarkConcurrentWrites(b *testing.B) {
  1159  	if !integrationTest {
  1160  		b.Skip("only makes sense when running against production service")
  1161  	}
  1162  	for n := 1; n <= 32; n *= 2 {
  1163  		b.Run(fmt.Sprint(n), func(b *testing.B) {
  1164  			b.StopTimer()
  1165  			lg := client.Logger(testLogID, logging.ConcurrentWriteLimit(n), logging.EntryCountThreshold(1000))
  1166  			const (
  1167  				nEntries = 1e5
  1168  				payload  = "the quick brown fox jumps over the lazy dog"
  1169  			)
  1170  			b.SetBytes(int64(nEntries * len(payload)))
  1171  			b.StartTimer()
  1172  			for i := 0; i < b.N; i++ {
  1173  				for j := 0; j < nEntries; j++ {
  1174  					lg.Log(logging.Entry{Payload: payload})
  1175  				}
  1176  				if err := lg.Flush(); err != nil {
  1177  					b.Fatal(err)
  1178  				}
  1179  			}
  1180  		})
  1181  	}
  1182  }
  1183  
  1184  func TestSeverityUnmarshal(t *testing.T) {
  1185  	j := []byte(`{"logName": "test-log","severity": "ERROR","payload": "test"}`)
  1186  	var entry logging.Entry
  1187  	err := json.Unmarshal(j, &entry)
  1188  	if err != nil {
  1189  		t.Fatalf("en.Unmarshal: %v", err)
  1190  	}
  1191  	if entry.Severity != logging.Error {
  1192  		t.Fatalf("Severity: got %v, want %v", entry.Severity, logging.Error)
  1193  	}
  1194  }
  1195  
  1196  func TestSeverityAsNumberUnmarshal(t *testing.T) {
  1197  	j := []byte(fmt.Sprintf(`{"logName": "test-log","severity": %d, "payload": "test"}`, logging.Info))
  1198  	var entry logging.Entry
  1199  	err := json.Unmarshal(j, &entry)
  1200  	if err != nil {
  1201  		t.Fatalf("en.Unmarshal: %v", err)
  1202  	}
  1203  	if entry.Severity != logging.Info {
  1204  		t.Fatalf("Severity: got %v, want %v", entry.Severity, logging.Info)
  1205  	}
  1206  }
  1207  
  1208  func TestSeverityMarshalThenUnmarshal(t *testing.T) {
  1209  	entry := logging.Entry{Severity: logging.Warning, Payload: "test"}
  1210  	j, err := json.Marshal(entry)
  1211  	if err != nil {
  1212  		t.Fatalf("en.Marshal: %v", err)
  1213  	}
  1214  
  1215  	var entryU logging.Entry
  1216  
  1217  	err = json.Unmarshal(j, &entryU)
  1218  	if err != nil {
  1219  		t.Fatalf("en.Unmarshal: %v", err)
  1220  	}
  1221  
  1222  	if entryU.Severity != logging.Warning {
  1223  		t.Fatalf("Severity: got %v, want %v", entryU.Severity, logging.Warning)
  1224  	}
  1225  }
  1226  
  1227  func TestSourceLocationPopulation(t *testing.T) {
  1228  	tests := []struct {
  1229  		name   string
  1230  		logger *logging.Logger
  1231  		in     logging.Entry
  1232  		want   *logpb.LogEntrySourceLocation
  1233  	}{
  1234  		{
  1235  			name:   "populate source location for debug entry when allowed",
  1236  			logger: client.Logger("test-source-location", logging.SourceLocationPopulation(logging.PopulateSourceLocationForDebugEntries)),
  1237  			in: logging.Entry{
  1238  				Severity: logging.Severity(logging.Debug),
  1239  			},
  1240  			// want field will be patched to setup actual code line and function name
  1241  			want: nil,
  1242  		}, {
  1243  			name:   "populate source location for non-debug entry when allowed",
  1244  			logger: client.Logger("test-source-location", logging.SourceLocationPopulation(logging.AlwaysPopulateSourceLocation)),
  1245  			in: logging.Entry{
  1246  				Severity: logging.Severity(logging.Default),
  1247  			},
  1248  			// want field will be patched to setup actual code line and function name
  1249  			want: nil,
  1250  		}, {
  1251  			name:   "do not populate source location for debug entry with source location",
  1252  			logger: client.Logger("test-source-location", logging.SourceLocationPopulation(logging.PopulateSourceLocationForDebugEntries)),
  1253  			in: logging.Entry{
  1254  				Severity: logging.Severity(logging.Debug),
  1255  				SourceLocation: &logpb.LogEntrySourceLocation{
  1256  					File:     "test_source_file.go",
  1257  					Function: "testFunction",
  1258  					Line:     65536,
  1259  				},
  1260  			},
  1261  			want: &logpb.LogEntrySourceLocation{
  1262  				File:     "test_source_file.go",
  1263  				Function: "testFunction",
  1264  				Line:     65536,
  1265  			},
  1266  		}, {
  1267  			name:   "do not populate source location for non-debug entry when only allowed for debug",
  1268  			logger: client.Logger("test-source-location", logging.SourceLocationPopulation(logging.PopulateSourceLocationForDebugEntries)),
  1269  			in: logging.Entry{
  1270  				Severity: logging.Severity(logging.Info),
  1271  			},
  1272  			want: nil,
  1273  		}, {
  1274  			name:   "do not populate source location when not allowed for any",
  1275  			logger: client.Logger("test-source-location", logging.SourceLocationPopulation(logging.DoNotPopulateSourceLocation)),
  1276  			in: logging.Entry{
  1277  				Severity: logging.Severity(logging.Debug),
  1278  			},
  1279  			want: nil,
  1280  		}, {
  1281  			name:   "do not populate source location by default",
  1282  			logger: client.Logger("test-source-location"),
  1283  			in: logging.Entry{
  1284  				Severity: logging.Severity(logging.Debug),
  1285  			},
  1286  			want: nil,
  1287  		},
  1288  	}
  1289  
  1290  	for index, tc := range tests {
  1291  		t.Run(tc.name, func(t *testing.T) {
  1292  			// patch first two want results to produce correct source info
  1293  			if index < 2 {
  1294  				pc, file, line, ok := runtime.Caller(0)
  1295  				if !ok {
  1296  					t.Fatalf("Unexpected error: %+v: failed to call runtime.Caller()", tc.in)
  1297  				}
  1298  				details := runtime.FuncForPC(pc)
  1299  				tc.want = &logpb.LogEntrySourceLocation{
  1300  					File:     file,
  1301  					Function: details.Name(),
  1302  					Line:     int64(line + 11), // 11 code lines between runtime.Caller() and logging.ToLogEntry()
  1303  				}
  1304  			}
  1305  			e, err := tc.logger.ToLogEntry(tc.in, "projects/P")
  1306  			if err != nil {
  1307  				t.Fatalf("Unexpected error: %+v: %v", tc.in, err)
  1308  			}
  1309  
  1310  			if e.SourceLocation != tc.want {
  1311  				if diff := cmp.Diff(e.SourceLocation, tc.want, cmpopts.IgnoreUnexported(logpb.LogEntrySourceLocation{})); diff != "" {
  1312  					t.Errorf("got(-),want(+):\n%s", diff)
  1313  				}
  1314  			}
  1315  		})
  1316  	}
  1317  }
  1318  
  1319  func BenchmarkSourceLocationPopulation(b *testing.B) {
  1320  	logger := *client.Logger("test-source-location", logging.SourceLocationPopulation(logging.PopulateSourceLocationForDebugEntries))
  1321  	tests := []struct {
  1322  		name string
  1323  		in   logging.Entry
  1324  	}{
  1325  		{
  1326  			name: "with source location population",
  1327  			in: logging.Entry{
  1328  				Severity: logging.Severity(logging.Debug),
  1329  			},
  1330  		}, {
  1331  			name: "without source location population",
  1332  			in: logging.Entry{
  1333  				Severity: logging.Severity(logging.Info),
  1334  			},
  1335  		},
  1336  	}
  1337  	var err error
  1338  	for _, tc := range tests {
  1339  		b.Run(tc.name, func(b *testing.B) {
  1340  			for n := 0; n < b.N; n++ {
  1341  				_, err = logger.ToLogEntry(tc.in, "projects/P")
  1342  				if err != nil {
  1343  					b.Fatalf("Unexpected error: %+v: %v", tc.in, err)
  1344  				}
  1345  			}
  1346  		})
  1347  	}
  1348  }
  1349  
  1350  // writeLogEntriesTestHandler is a fake Logging backend handler used to test partialSuccess option logic
  1351  type writeLogEntriesTestHandler struct {
  1352  	logpb.UnimplementedLoggingServiceV2Server
  1353  	hook func(*logpb.WriteLogEntriesRequest)
  1354  }
  1355  
  1356  func (f *writeLogEntriesTestHandler) WriteLogEntries(_ context.Context, e *logpb.WriteLogEntriesRequest) (*logpb.WriteLogEntriesResponse, error) {
  1357  	if f.hook != nil {
  1358  		f.hook(e)
  1359  	}
  1360  	return &logpb.WriteLogEntriesResponse{}, nil
  1361  }
  1362  
  1363  func fakeClient(parent string, writeLogEntryHandler func(e *logpb.WriteLogEntriesRequest), serverOptions ...grpc.ServerOption) (*logging.Client, error) {
  1364  	// setup fake server
  1365  	fakeBackend := &writeLogEntriesTestHandler{}
  1366  	l, err := net.Listen("tcp", "localhost:0")
  1367  	if err != nil {
  1368  		return nil, err
  1369  	}
  1370  	gsrv := grpc.NewServer(serverOptions...)
  1371  	logpb.RegisterLoggingServiceV2Server(gsrv, fakeBackend)
  1372  	fakeServerAddr := l.Addr().String()
  1373  	go func() {
  1374  		if err := gsrv.Serve(l); err != nil {
  1375  			panic(err)
  1376  		}
  1377  	}()
  1378  	fakeBackend.hook = writeLogEntryHandler
  1379  	ctx := context.Background()
  1380  	client, _ := logging.NewClient(ctx, parent, option.WithEndpoint(fakeServerAddr),
  1381  		option.WithoutAuthentication(),
  1382  		option.WithGRPCDialOption(grpc.WithInsecure()))
  1383  	return client, nil
  1384  }
  1385  
  1386  func TestPartialSuccessOption(t *testing.T) {
  1387  	var logger *logging.Logger
  1388  	var partialSuccess bool
  1389  
  1390  	entry := logging.Entry{Payload: "payload string"}
  1391  	tests := []struct {
  1392  		name string
  1393  		do   func()
  1394  	}{
  1395  		{
  1396  			name: "use PartialSuccess with LogSync",
  1397  			do: func() {
  1398  				logger.LogSync(context.Background(), entry)
  1399  			},
  1400  		},
  1401  		{
  1402  			name: "use PartialSuccess with Log",
  1403  			do: func() {
  1404  				logger.Log(entry)
  1405  				logger.Flush()
  1406  			},
  1407  		},
  1408  	}
  1409  
  1410  	// setup fake client
  1411  	client, err := fakeClient("projects/test", func(e *logpb.WriteLogEntriesRequest) {
  1412  		partialSuccess = e.PartialSuccess
  1413  	})
  1414  	if err != nil {
  1415  		t.Fatal(err)
  1416  	}
  1417  	defer client.Close()
  1418  	logger = client.Logger("abc", logging.PartialSuccess())
  1419  
  1420  	for _, tc := range tests {
  1421  		t.Run(tc.name, func(t *testing.T) {
  1422  			partialSuccess = false
  1423  			tc.do()
  1424  			if !partialSuccess {
  1425  				t.Fatal("e.PartialSuccess = false, want true")
  1426  			}
  1427  		})
  1428  	}
  1429  }
  1430  
  1431  func TestWriteLogEntriesSizeLimit(t *testing.T) {
  1432  	// Test that logging too many large requests at once doesn't bump up
  1433  	// against WriteLogEntriesRequest size limit
  1434  	sizeLimit := 10485760 // 10MiB size limit
  1435  
  1436  	// Create a fake client whose server can only handle messages of at most sizeLimit
  1437  	client, err := fakeClient("projects/test", func(e *logpb.WriteLogEntriesRequest) {}, grpc.MaxRecvMsgSize(sizeLimit))
  1438  	if err != nil {
  1439  		t.Fatal(err)
  1440  	}
  1441  
  1442  	client.OnError = func(e error) {
  1443  		t.Fatalf(e.Error())
  1444  	}
  1445  
  1446  	defer client.Close()
  1447  	logger := client.Logger("test")
  1448  	entry := logging.Entry{Payload: strings.Repeat("1", 250000)}
  1449  
  1450  	for i := 0; i < 200; i++ {
  1451  		logger.Log(entry)
  1452  	}
  1453  }
  1454  
  1455  func TestRedirectOutputIngestion(t *testing.T) {
  1456  	var hookCalled bool
  1457  
  1458  	// setup fake client
  1459  	client, err := fakeClient("projects/test", func(e *logpb.WriteLogEntriesRequest) {
  1460  		hookCalled = true
  1461  	})
  1462  	if err != nil {
  1463  		t.Fatal(err)
  1464  	}
  1465  	defer client.Close()
  1466  
  1467  	entry := logging.Entry{Payload: "testing payload string"}
  1468  	tests := []struct {
  1469  		name   string
  1470  		logger *logging.Logger
  1471  		want   bool
  1472  	}{
  1473  		{
  1474  			name:   "redirect output does not ingest",
  1475  			logger: client.Logger("stdout-redirection-log", logging.RedirectAsJSON(os.Stdout)),
  1476  			want:   false,
  1477  		},
  1478  		{
  1479  			name:   "log without Redirect flags ingest",
  1480  			logger: client.Logger("default-ingestion-log"),
  1481  			want:   true,
  1482  		},
  1483  	}
  1484  	for _, tc := range tests {
  1485  		t.Run(tc.name, func(t *testing.T) {
  1486  			hookCalled = false
  1487  			tc.logger.LogSync(context.Background(), entry)
  1488  			if hookCalled != tc.want {
  1489  				t.Errorf("Log ingestion works unexpected: got %v want %v\n", hookCalled, tc.want)
  1490  			}
  1491  		})
  1492  	}
  1493  }
  1494  
  1495  func TestRedirectOutputFormats(t *testing.T) {
  1496  	testURL, _ := url.Parse("https://example.com/test")
  1497  	tests := []struct {
  1498  		name      string
  1499  		in        *logging.Entry
  1500  		want      string
  1501  		wantError error
  1502  	}{
  1503  		{
  1504  			name: "full data redirect with text payload",
  1505  			in: &logging.Entry{
  1506  				Labels:       map[string]string{"key1": "value1", "key2": "value2"},
  1507  				Timestamp:    testNow().UTC(),
  1508  				Severity:     logging.Debug,
  1509  				InsertID:     "0000AAA01",
  1510  				Trace:        "projects/P/ABCD12345678AB12345678",
  1511  				SpanID:       "000000000001",
  1512  				TraceSampled: true,
  1513  				SourceLocation: &logpb.LogEntrySourceLocation{
  1514  					File:     "acme.go",
  1515  					Function: "main",
  1516  					Line:     100,
  1517  				},
  1518  				Operation: &logpb.LogEntryOperation{
  1519  					Id:       "0123456789",
  1520  					Producer: "test",
  1521  				},
  1522  				HTTPRequest: &logging.HTTPRequest{
  1523  					Request: &http.Request{
  1524  						URL:    testURL,
  1525  						Method: "POST",
  1526  					},
  1527  				},
  1528  
  1529  				Payload: "this is text payload",
  1530  			},
  1531  			want: `{"httpRequest":{"requestMethod":"POST","requestUrl":"https://example.com/test"},"logging.googleapis.com/insertId":"0000AAA01",` +
  1532  				`"logging.googleapis.com/labels":{"key1":"value1","key2":"value2"},"logging.googleapis.com/operation":{"id":"0123456789","producer":"test"},` +
  1533  				`"logging.googleapis.com/sourceLocation":{"file":"acme.go","function":"main","line":"100"},"logging.googleapis.com/spanId":"000000000001",` +
  1534  				`"logging.googleapis.com/trace":"projects/P/ABCD12345678AB12345678","logging.googleapis.com/trace_sampled":true,` +
  1535  				`"message":"this is text payload","severity":"DEBUG","timestamp":"seconds:1000"}`,
  1536  		},
  1537  		{
  1538  			name: "full data redirect with json payload",
  1539  			in: &logging.Entry{
  1540  				Labels:       map[string]string{"key1": "value1", "key2": "value2"},
  1541  				Timestamp:    testNow().UTC(),
  1542  				Severity:     logging.Debug,
  1543  				InsertID:     "0000AAA01",
  1544  				Trace:        "projects/P/ABCD12345678AB12345678",
  1545  				SpanID:       "000000000001",
  1546  				TraceSampled: true,
  1547  				SourceLocation: &logpb.LogEntrySourceLocation{
  1548  					File:     "acme.go",
  1549  					Function: "main",
  1550  					Line:     100,
  1551  				},
  1552  				Operation: &logpb.LogEntryOperation{
  1553  					Id:       "0123456789",
  1554  					Producer: "test",
  1555  				},
  1556  				HTTPRequest: &logging.HTTPRequest{
  1557  					Request: &http.Request{
  1558  						URL:    testURL,
  1559  						Method: "POST",
  1560  					},
  1561  				},
  1562  				Payload: map[string]interface{}{
  1563  					"Message": "message part of the payload",
  1564  					"Latency": 321,
  1565  				},
  1566  			},
  1567  			want: `{"httpRequest":{"requestMethod":"POST","requestUrl":"https://example.com/test"},"logging.googleapis.com/insertId":"0000AAA01",` +
  1568  				`"logging.googleapis.com/labels":{"key1":"value1","key2":"value2"},"logging.googleapis.com/operation":{"id":"0123456789","producer":"test"},` +
  1569  				`"logging.googleapis.com/sourceLocation":{"file":"acme.go","function":"main","line":"100"},"logging.googleapis.com/spanId":"000000000001",` +
  1570  				`"logging.googleapis.com/trace":"projects/P/ABCD12345678AB12345678","logging.googleapis.com/trace_sampled":true,` +
  1571  				`"message":{"Latency":321,"Message":"message part of the payload"},"severity":"DEBUG","timestamp":"seconds:1000"}`,
  1572  		},
  1573  		{
  1574  			name: "error on redirect with proto payload",
  1575  			in: &logging.Entry{
  1576  				Timestamp: testNow().UTC(),
  1577  				Severity:  logging.Debug,
  1578  				Payload:   &anypb.Any{},
  1579  			},
  1580  			wantError: logging.ErrRedirectProtoPayloadNotSupported,
  1581  		},
  1582  	}
  1583  	buffer := &strings.Builder{}
  1584  	logger := client.Logger("test-redirect-output", logging.RedirectAsJSON(buffer))
  1585  	for _, tc := range tests {
  1586  		t.Run(tc.name, func(t *testing.T) {
  1587  			buffer.Reset()
  1588  			err := logger.LogSync(context.Background(), *tc.in)
  1589  			if err != nil {
  1590  				if tc.wantError == nil {
  1591  					t.Fatalf("Unexpected error: %+v: %v", tc.in, err)
  1592  				}
  1593  				if tc.wantError != err {
  1594  					t.Errorf("Expected error: %+v, got: %v want: %v\n", tc.in, err, tc.wantError)
  1595  				}
  1596  			} else {
  1597  				if tc.wantError != nil {
  1598  					t.Errorf("Expected error: %+v, want: %v\n", tc.in, tc.wantError)
  1599  				}
  1600  				got := strings.TrimSpace(buffer.String())
  1601  
  1602  				// Compare structure equivalence of the outputs, not string equivalence, as order doesn't matter.
  1603  				var gotJson, wantJson interface{}
  1604  
  1605  				err = json.Unmarshal([]byte(got), &gotJson)
  1606  				if err != nil {
  1607  					t.Errorf("Error when serializing JSON output: %v", err)
  1608  				}
  1609  
  1610  				err = json.Unmarshal([]byte(tc.want), &wantJson)
  1611  				if err != nil {
  1612  					t.Fatalf("Error unmarshalling JSON input for want: %v", err)
  1613  				}
  1614  
  1615  				if !reflect.DeepEqual(gotJson, wantJson) {
  1616  					t.Errorf("TestRedirectOutputFormats: %+v: got %v, want %v", tc.in, got, tc.want)
  1617  				}
  1618  			}
  1619  		})
  1620  	}
  1621  }
  1622  
  1623  func TestInstrumentationIngestion(t *testing.T) {
  1624  	var got []*logpb.LogEntry
  1625  
  1626  	// setup fake client
  1627  	client, err := fakeClient("projects/test", func(e *logpb.WriteLogEntriesRequest) {
  1628  		got = e.GetEntries()
  1629  	})
  1630  	if err != nil {
  1631  		t.Fatal(err)
  1632  	}
  1633  	defer client.Close()
  1634  
  1635  	entry := &logging.Entry{Severity: logging.Info, Payload: "test string"}
  1636  	logger := client.Logger("test-instrumentation")
  1637  	tests := []struct {
  1638  		entryLen      int
  1639  		hasDiagnostic bool
  1640  	}{
  1641  		{
  1642  			entryLen:      2,
  1643  			hasDiagnostic: true,
  1644  		},
  1645  		{
  1646  			entryLen:      1,
  1647  			hasDiagnostic: false,
  1648  		},
  1649  	}
  1650  	onceBackup := internal.InstrumentOnce
  1651  	internal.InstrumentOnce = new(sync.Once)
  1652  	for _, test := range tests {
  1653  		got = nil
  1654  		err := logger.LogSync(context.Background(), *entry)
  1655  		if err != nil {
  1656  			t.Fatal(err)
  1657  		}
  1658  		if len(got) != test.entryLen {
  1659  			t.Errorf("got(%v), want(%v)", got, test.entryLen)
  1660  		}
  1661  		diagnosticEntry := false
  1662  		for _, ent := range got {
  1663  			if internal.LogIDFromPath("projects/test", ent.LogName) == "diagnostic-log" {
  1664  				diagnosticEntry = true
  1665  				break
  1666  			}
  1667  		}
  1668  		if diagnosticEntry != test.hasDiagnostic {
  1669  			t.Errorf("instrumentation entry misplaced: got(%v), want(%v)", diagnosticEntry, test.hasDiagnostic)
  1670  		}
  1671  	}
  1672  	internal.InstrumentOnce = onceBackup
  1673  }
  1674  
  1675  func TestInstrumentationWithRedirect(t *testing.T) {
  1676  	want := []string{
  1677  		// do not format the string to preserve expected new-line between messages
  1678  		`{"message":"test string","severity":"INFO","timestamp":"seconds:1000"}
  1679  {"message":{"logging.googleapis.com/diagnostic":{"instrumentation_source":[{"name":"go","version":"` + internal.Version + `"}],"runtime":"` + internal.VersionGo() + `"}},"severity":"DEFAULT","timestamp":"seconds:1000"}`,
  1680  		`{"message":"test string","severity":"INFO","timestamp":"seconds:1000"}`,
  1681  	}
  1682  	entry := &logging.Entry{Severity: logging.Info, Payload: "test string"}
  1683  	buffer := &strings.Builder{}
  1684  	logger := client.Logger("test-redirect-output", logging.RedirectAsJSON(buffer))
  1685  	onceBackup, timeBackup := internal.InstrumentOnce, logging.SetNow(testNow)
  1686  	internal.InstrumentOnce = new(sync.Once)
  1687  	for i := range want {
  1688  		buffer.Reset()
  1689  		err := logger.LogSync(context.Background(), *entry)
  1690  		if err != nil {
  1691  			t.Fatal(err)
  1692  		}
  1693  		got := strings.TrimSpace(buffer.String())
  1694  		if got != want[i] {
  1695  			t.Errorf("got(%v), want(%v)", got, want[i])
  1696  		}
  1697  	}
  1698  	logging.SetNow(timeBackup)
  1699  	internal.InstrumentOnce = onceBackup
  1700  }
  1701  
  1702  func ExampleRedirectAsJSON_withStdout() {
  1703  	logger := client.Logger("redirect-to-stdout", logging.RedirectAsJSON(os.Stdout))
  1704  	logger.Log(logging.Entry{Severity: logging.Debug, Payload: "redirected log"})
  1705  }
  1706  

View as plain text