| // Copyright 2016 Google LLC |
| // |
| // Licensed under the Apache License, Version 2.0 (the "License"); |
| // you may not use this file except in compliance with the License. |
| // You may obtain a copy of the License at |
| // |
| // http://www.apache.org/licenses/LICENSE-2.0 |
| // |
| // Unless required by applicable law or agreed to in writing, software |
| // distributed under the License is distributed on an "AS IS" BASIS, |
| // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
| // See the License for the specific language governing permissions and |
| // limitations under the License. |
| |
| // TODO(jba): test that OnError is getting called appropriately. |
| |
| package logging_test |
| |
| import ( |
| "context" |
| "encoding/json" |
| "errors" |
| "flag" |
| "fmt" |
| "log" |
| "math/rand" |
| "net" |
| "net/http" |
| "net/url" |
| "os" |
| "path/filepath" |
| "reflect" |
| "runtime" |
| "strings" |
| "sync" |
| "sync/atomic" |
| "testing" |
| "time" |
| |
| cinternal "cloud.google.com/go/internal" |
| "cloud.google.com/go/internal/testutil" |
| "cloud.google.com/go/internal/uid" |
| "cloud.google.com/go/logging" |
| logpb "cloud.google.com/go/logging/apiv2/loggingpb" |
| "cloud.google.com/go/logging/internal" |
| ltesting "cloud.google.com/go/logging/internal/testing" |
| "cloud.google.com/go/logging/logadmin" |
| "github.com/google/go-cmp/cmp" |
| "github.com/google/go-cmp/cmp/cmpopts" |
| gax "github.com/googleapis/gax-go/v2" |
| "golang.org/x/oauth2" |
| "google.golang.org/api/iterator" |
| "google.golang.org/api/option" |
| mrpb "google.golang.org/genproto/googleapis/api/monitoredres" |
| "google.golang.org/grpc" |
| "google.golang.org/grpc/codes" |
| "google.golang.org/grpc/status" |
| "google.golang.org/protobuf/types/known/anypb" |
| ) |
| |
| const testLogIDPrefix = "GO-LOGGING-CLIENT/TEST-LOG" |
| |
| var ( |
| client *logging.Client |
| aclient *logadmin.Client |
| testProjectID string |
| testLogID string |
| testFilter string |
| errorc chan error |
| ctx context.Context |
| |
| // Adjust the fields of a FullEntry received from the production service |
| // before comparing it with the expected result. We can't correctly |
| // compare certain fields, like times or server-generated IDs. |
| clean func(*logging.Entry) |
| |
| // Create a new client with the given project ID. |
| newClients func(ctx context.Context, projectID string) (*logging.Client, *logadmin.Client) |
| |
| uids = uid.NewSpace(testLogIDPrefix, nil) |
| |
| // If true, this test is using the production service, not a fake. |
| integrationTest bool |
| ) |
| |
| func testNow() time.Time { |
| return time.Unix(1000, 0) |
| } |
| |
| func TestMain(m *testing.M) { |
| flag.Parse() // needed for testing.Short() |
| |
| // disable ingesting instrumentation log entry |
| internal.InstrumentOnce.Do(func() {}) |
| |
| ctx = context.Background() |
| testProjectID = testutil.ProjID() |
| errorc = make(chan error, 100) |
| if testProjectID == "" || testing.Short() { |
| integrationTest = false |
| if testProjectID != "" { |
| log.Print("Integration tests skipped in short mode (using fake instead)") |
| } |
| testProjectID = ltesting.ValidProjectID |
| clean = func(e *logging.Entry) { |
| // Remove the insert ID for consistency with the integration test. |
| e.InsertID = "" |
| } |
| |
| addr, err := ltesting.NewServer() |
| if err != nil { |
| log.Fatalf("creating fake server: %v", err) |
| } |
| logging.SetNow(testNow) |
| |
| newClients = func(ctx context.Context, parent string) (*logging.Client, *logadmin.Client) { |
| conn, err := grpc.Dial(addr, grpc.WithInsecure()) |
| if err != nil { |
| log.Fatalf("dialing %q: %v", addr, err) |
| } |
| c, err := logging.NewClient(ctx, parent, option.WithGRPCConn(conn)) |
| if err != nil { |
| log.Fatalf("creating client for fake at %q: %v", addr, err) |
| } |
| ac, err := logadmin.NewClient(ctx, parent, option.WithGRPCConn(conn)) |
| if err != nil { |
| log.Fatalf("creating client for fake at %q: %v", addr, err) |
| } |
| return c, ac |
| } |
| |
| } else { |
| integrationTest = true |
| clean = func(e *logging.Entry) { |
| // We cannot compare timestamps, so set them to the test time. |
| // Also, remove the insert ID added by the service. |
| e.Timestamp = testNow().UTC() |
| e.InsertID = "" |
| } |
| ts := testutil.TokenSource(ctx, logging.AdminScope) |
| if ts == nil { |
| log.Fatal("The project key must be set. See CONTRIBUTING.md for details") |
| } |
| log.Printf("running integration tests with project %s", testProjectID) |
| newClients = func(ctx context.Context, parent string) (*logging.Client, *logadmin.Client) { |
| c, err := logging.NewClient(ctx, parent, option.WithTokenSource(ts)) |
| if err != nil { |
| log.Fatalf("creating prod client: %v", err) |
| } |
| ac, err := logadmin.NewClient(ctx, parent, option.WithTokenSource(ts)) |
| if err != nil { |
| log.Fatalf("creating prod client: %v", err) |
| } |
| return c, ac |
| } |
| |
| } |
| client, aclient = newClients(ctx, testProjectID) |
| client.OnError = func(e error) { errorc <- e } |
| |
| exit := m.Run() |
| os.Exit(exit) |
| } |
| |
| func initLogs() { |
| testLogID = uids.New() |
| hourAgo := time.Now().Add(-1 * time.Hour).UTC() |
| testFilter = fmt.Sprintf(`logName = "projects/%s/logs/%s" AND |
| timestamp >= "%s"`, |
| testProjectID, strings.Replace(testLogID, "/", "%2F", -1), hourAgo.Format(time.RFC3339)) |
| } |
| |
| func TestLogSync(t *testing.T) { |
| initLogs() // Generate new testLogID |
| ctx := context.Background() |
| lg := client.Logger(testLogID) |
| err := lg.LogSync(ctx, logging.Entry{Payload: "hello"}) |
| if err != nil { |
| t.Fatal(err) |
| } |
| err = lg.LogSync(ctx, logging.Entry{Payload: "goodbye"}) |
| if err != nil { |
| t.Fatal(err) |
| } |
| // Allow overriding the MonitoredResource. |
| err = lg.LogSync(ctx, logging.Entry{Payload: "mr", Resource: &mrpb.MonitoredResource{Type: "global"}}) |
| if err != nil { |
| t.Fatal(err) |
| } |
| |
| want := []*logging.Entry{ |
| entryForTesting("hello"), |
| entryForTesting("goodbye"), |
| entryForTesting("mr"), |
| } |
| var got []*logging.Entry |
| ok := waitFor(func() bool { |
| got, err = allTestLogEntries(ctx) |
| if err != nil { |
| t.Log("fetching log entries: ", err) |
| return false |
| } |
| return len(got) == len(want) |
| }) |
| if !ok { |
| t.Fatalf("timed out; got: %d, want: %d\n", len(got), len(want)) |
| } |
| if msg, ok := compareEntries(got, want); !ok { |
| t.Error(msg) |
| } |
| } |
| |
| func TestLogAndEntries(t *testing.T) { |
| initLogs() // Generate new testLogID |
| ctx := context.Background() |
| payloads := []string{"p1", "p2", "p3", "p4", "p5"} |
| lg := client.Logger(testLogID) |
| for _, p := range payloads { |
| // Use the insert ID to guarantee iteration order. |
| lg.Log(logging.Entry{Payload: p, InsertID: p}) |
| } |
| if err := lg.Flush(); err != nil { |
| t.Fatal(err) |
| } |
| var want []*logging.Entry |
| for _, p := range payloads { |
| want = append(want, entryForTesting(p)) |
| } |
| var got []*logging.Entry |
| ok := waitFor(func() bool { |
| var err error |
| got, err = allTestLogEntries(ctx) |
| if err != nil { |
| t.Log("fetching log entries: ", err) |
| return false |
| } |
| return len(got) == len(want) |
| }) |
| if !ok { |
| t.Fatalf("timed out; got: %d, want: %d\n", len(got), len(want)) |
| } |
| if msg, ok := compareEntries(got, want); !ok { |
| t.Error(msg) |
| } |
| } |
| |
| func TestLogInvalidUtf8(t *testing.T) { |
| lg := client.Logger(testLogID) |
| msg := fmt.Sprintf("\x6c\x6f\x67\xe5") |
| lg.Log(logging.Entry{ |
| Payload: msg, |
| Timestamp: time.Now(), |
| }) |
| err := lg.Flush() |
| s, _ := status.FromError(err) |
| if !strings.Contains(s.Message(), "string field contains invalid UTF-8") { |
| t.Fatalf("got an incorrect error: %v", err) |
| } |
| } |
| |
| func TestContextFunc(t *testing.T) { |
| initLogs() |
| var contextFuncCalls, cleanupCalls int32 //atomic |
| |
| lg := client.Logger(testLogID, logging.ContextFunc(func() (context.Context, func()) { |
| atomic.AddInt32(&contextFuncCalls, 1) |
| return context.Background(), func() { atomic.AddInt32(&cleanupCalls, 1) } |
| })) |
| lg.Log(logging.Entry{Payload: "p"}) |
| if err := lg.Flush(); err != nil { |
| t.Fatal(err) |
| } |
| got1 := atomic.LoadInt32(&contextFuncCalls) |
| got2 := atomic.LoadInt32(&cleanupCalls) |
| if got1 != 1 || got1 != got2 { |
| t.Errorf("got %d calls to context func, %d calls to cleanup func; want 1, 1", got1, got2) |
| } |
| } |
| |
| func TestToLogEntry(t *testing.T) { |
| u := &url.URL{Scheme: "http"} |
| tests := []struct { |
| name string |
| in logging.Entry |
| want *logpb.LogEntry |
| wantError error |
| }{ |
| { |
| name: "BlankLogEntry", |
| in: logging.Entry{}, |
| want: &logpb.LogEntry{}, |
| }, { |
| name: "Already set Trace", |
| in: logging.Entry{Trace: "t1"}, |
| want: &logpb.LogEntry{Trace: "t1"}, |
| }, { |
| name: "No X-Trace-Context header", |
| in: logging.Entry{ |
| HTTPRequest: &logging.HTTPRequest{ |
| Request: &http.Request{URL: u, Header: http.Header{"foo": {"bar"}}}, |
| }, |
| }, |
| want: &logpb.LogEntry{}, |
| }, { |
| name: "X-Trace-Context header with all fields", |
| in: logging.Entry{ |
| TraceSampled: false, |
| HTTPRequest: &logging.HTTPRequest{ |
| Request: &http.Request{ |
| URL: u, |
| Header: http.Header{"X-Cloud-Trace-Context": {"105445aa7843bc8bf206b120001000/000000000000004a;o=1"}}, |
| }, |
| }, |
| }, |
| want: &logpb.LogEntry{ |
| Trace: "projects/P/traces/105445aa7843bc8bf206b120001000", |
| SpanId: "000000000000004a", |
| TraceSampled: true, |
| }, |
| }, { |
| name: "X-Trace-Context header with all fields; TraceSampled explicitly set", |
| in: logging.Entry{ |
| TraceSampled: true, |
| HTTPRequest: &logging.HTTPRequest{ |
| Request: &http.Request{ |
| URL: u, |
| Header: http.Header{"X-Cloud-Trace-Context": {"105445aa7843bc8bf206b120001000/000000000000004a;o=0"}}, |
| }, |
| }, |
| }, |
| want: &logpb.LogEntry{ |
| Trace: "projects/P/traces/105445aa7843bc8bf206b120001000", |
| SpanId: "000000000000004a", |
| TraceSampled: true, |
| }, |
| }, { |
| name: "X-Trace-Context header with all fields; TraceSampled from Header", |
| in: logging.Entry{ |
| HTTPRequest: &logging.HTTPRequest{ |
| Request: &http.Request{ |
| URL: u, |
| Header: http.Header{"X-Cloud-Trace-Context": {"105445aa7843bc8bf206b120001000/000000000000004a;o=1"}}, |
| }, |
| }, |
| }, |
| want: &logpb.LogEntry{ |
| Trace: "projects/P/traces/105445aa7843bc8bf206b120001000", |
| SpanId: "000000000000004a", |
| TraceSampled: true, |
| }, |
| }, { |
| name: "X-Trace-Context header with blank trace", |
| in: logging.Entry{ |
| HTTPRequest: &logging.HTTPRequest{ |
| Request: &http.Request{ |
| URL: u, |
| Header: http.Header{"X-Cloud-Trace-Context": {"/0;o=1"}}, |
| }, |
| }, |
| }, |
| want: &logpb.LogEntry{}, |
| }, { |
| name: "X-Trace-Context header with blank span", |
| in: logging.Entry{ |
| HTTPRequest: &logging.HTTPRequest{ |
| Request: &http.Request{ |
| URL: u, |
| Header: http.Header{"X-Cloud-Trace-Context": {"105445aa7843bc8bf206b120001000/;o=0"}}, |
| }, |
| }, |
| }, |
| want: &logpb.LogEntry{ |
| Trace: "projects/P/traces/105445aa7843bc8bf206b120001000", |
| }, |
| }, { |
| name: "X-Trace-Context header with missing traceSampled aka ?o=*", |
| in: logging.Entry{ |
| HTTPRequest: &logging.HTTPRequest{ |
| Request: &http.Request{ |
| URL: u, |
| Header: http.Header{"X-Cloud-Trace-Context": {"105445aa7843bc8bf206b120001000/0"}}, |
| }, |
| }, |
| }, |
| want: &logpb.LogEntry{ |
| Trace: "projects/P/traces/105445aa7843bc8bf206b120001000", |
| }, |
| }, { |
| name: "X-Trace-Context header with all blank fields", |
| in: logging.Entry{ |
| HTTPRequest: &logging.HTTPRequest{ |
| Request: &http.Request{ |
| URL: u, |
| Header: http.Header{"X-Cloud-Trace-Context": {""}}, |
| }, |
| }, |
| }, |
| want: &logpb.LogEntry{}, |
| }, { |
| name: "Invalid X-Trace-Context header but already set TraceID", |
| in: logging.Entry{ |
| HTTPRequest: &logging.HTTPRequest{ |
| Request: &http.Request{ |
| URL: u, |
| Header: http.Header{"X-Cloud-Trace-Context": {"t3"}}, |
| }, |
| }, |
| Trace: "t4", |
| }, |
| want: &logpb.LogEntry{ |
| Trace: "t4", |
| }, |
| }, { |
| name: "Already set TraceID and SpanID", |
| in: logging.Entry{Trace: "t1", SpanID: "007"}, |
| want: &logpb.LogEntry{ |
| Trace: "t1", |
| SpanId: "007", |
| }, |
| }, { |
| name: "Empty request produces an error", |
| in: logging.Entry{ |
| HTTPRequest: &logging.HTTPRequest{ |
| RequestSize: 128, |
| }, |
| }, |
| wantError: errors.New("logging: HTTPRequest must have a non-nil Request"), |
| }, |
| { |
| name: "Traceparent header with entry fields unset", |
| in: logging.Entry{ |
| HTTPRequest: &logging.HTTPRequest{ |
| Request: &http.Request{ |
| URL: u, |
| Header: http.Header{"Traceparent": {"00-105445aa7843bc8bf206b12000100012-000000000000004a-01"}}, |
| }, |
| }, |
| }, |
| want: &logpb.LogEntry{ |
| Trace: "projects/P/traces/105445aa7843bc8bf206b12000100012", |
| SpanId: "000000000000004a", |
| }, |
| }, |
| { |
| name: "traceparent header with preset sampled field", |
| in: logging.Entry{ |
| TraceSampled: true, |
| HTTPRequest: &logging.HTTPRequest{ |
| Request: &http.Request{ |
| URL: u, |
| Header: http.Header{"Traceparent": {"00-105445aa7843bc8bf206b12000100012-000000000000004a-00"}}, |
| }, |
| }, |
| }, |
| want: &logpb.LogEntry{ |
| Trace: "projects/P/traces/105445aa7843bc8bf206b12000100012", |
| SpanId: "000000000000004a", |
| TraceSampled: true, |
| }, |
| }, |
| { |
| name: "Traceparent header together with x-trace-context header", |
| in: logging.Entry{ |
| HTTPRequest: &logging.HTTPRequest{ |
| Request: &http.Request{ |
| URL: u, |
| Header: http.Header{ |
| "X-Cloud-Trace-Context": {"105445aa7843bc8bf206b120000000/0000000000000bbb;o=1"}, |
| "Traceparent": {"00-105445aa7843bc8bf206b1200010aaaa-0000000000000aaa-00"}}, |
| }, |
| }, |
| }, |
| want: &logpb.LogEntry{ |
| Trace: "projects/P/traces/105445aa7843bc8bf206b1200010aaaa", |
| SpanId: "0000000000000aaa", |
| }, |
| }, |
| { |
| name: "Traceparent header invalid protocol", |
| in: logging.Entry{ |
| HTTPRequest: &logging.HTTPRequest{ |
| Request: &http.Request{ |
| URL: u, |
| Header: http.Header{"Traceparent": {"01-105445aa7843bc8bf206b12000100012-000000000000004a-00"}}, |
| }, |
| }, |
| }, |
| want: &logpb.LogEntry{}, |
| }, |
| { |
| name: "Traceparent header short trace field", |
| in: logging.Entry{ |
| HTTPRequest: &logging.HTTPRequest{ |
| Request: &http.Request{ |
| URL: u, |
| Header: http.Header{"Traceparent": {"00-12345678901234567890-000000000000004a-00"}}, |
| }, |
| }, |
| }, |
| want: &logpb.LogEntry{}, |
| }, |
| { |
| name: "Traceparent header long trace field", |
| in: logging.Entry{ |
| HTTPRequest: &logging.HTTPRequest{ |
| Request: &http.Request{ |
| URL: u, |
| Header: http.Header{"Traceparent": {"00-1234567890123456789012345678901234567890-000000000000004a-00"}}, |
| }, |
| }, |
| }, |
| want: &logpb.LogEntry{}, |
| }, |
| { |
| name: "Traceparent header invalid trace field", |
| in: logging.Entry{ |
| HTTPRequest: &logging.HTTPRequest{ |
| Request: &http.Request{ |
| URL: u, |
| Header: http.Header{"Traceparent": {"00-123456789012345678901234567890xx-000000000000004a-00"}}, |
| }, |
| }, |
| }, |
| want: &logpb.LogEntry{}, |
| }, |
| { |
| name: "Traceparent header trace field all 0s", |
| in: logging.Entry{ |
| HTTPRequest: &logging.HTTPRequest{ |
| Request: &http.Request{ |
| URL: u, |
| Header: http.Header{"Traceparent": {"00-00000000000000000000000000000000-000000000000004a-00"}}, |
| }, |
| }, |
| }, |
| want: &logpb.LogEntry{}, |
| }, |
| { |
| name: "Traceparent header short span field", |
| in: logging.Entry{ |
| HTTPRequest: &logging.HTTPRequest{ |
| Request: &http.Request{ |
| URL: u, |
| Header: http.Header{"Traceparent": {"00-12345678901234567890123456789012-123456789012345-00"}}, |
| }, |
| }, |
| }, |
| want: &logpb.LogEntry{}, |
| }, |
| { |
| name: "Traceparent header long span field", |
| in: logging.Entry{ |
| HTTPRequest: &logging.HTTPRequest{ |
| Request: &http.Request{ |
| URL: u, |
| Header: http.Header{"Traceparent": {"00-12345678901234567890123456789012-12345678901234567890-00"}}, |
| }, |
| }, |
| }, |
| want: &logpb.LogEntry{}, |
| }, |
| { |
| name: "Traceparent header invalid span field", |
| in: logging.Entry{ |
| HTTPRequest: &logging.HTTPRequest{ |
| Request: &http.Request{ |
| URL: u, |
| Header: http.Header{"Traceparent": {"00-12345678901234567890123456789012-abcdefghijklmnop-00"}}, |
| }, |
| }, |
| }, |
| want: &logpb.LogEntry{}, |
| }, |
| { |
| name: "Traceparent header span field all 0s", |
| in: logging.Entry{ |
| HTTPRequest: &logging.HTTPRequest{ |
| Request: &http.Request{ |
| URL: u, |
| Header: http.Header{"Traceparent": {"00-12345678901234567890123456789012-0000000000000000-00"}}, |
| }, |
| }, |
| }, |
| want: &logpb.LogEntry{}, |
| }, |
| } |
| for _, test := range tests { |
| t.Run(test.name, func(t *testing.T) { |
| e, err := logging.ToLogEntry(test.in, "projects/P") |
| if err != nil && test.wantError == nil { |
| t.Fatalf("Unexpected error: %+v: %v", test.in, err) |
| } |
| if err == nil && test.wantError != nil { |
| t.Fatalf("Error is expected: %+v: %v", test.in, test.wantError) |
| } |
| if test.wantError != nil { |
| return |
| } |
| if got := e.Trace; got != test.want.Trace { |
| t.Errorf("TraceId: %+v: got %q, want %q", test.in, got, test.want.Trace) |
| } |
| if got := e.SpanId; got != test.want.SpanId { |
| t.Errorf("SpanId: %+v: got %q, want %q", test.in, got, test.want.SpanId) |
| } |
| if got := e.TraceSampled; got != test.want.TraceSampled { |
| t.Errorf("TraceSampled: %+v: got %t, want %t", test.in, got, test.want.TraceSampled) |
| } |
| }) |
| } |
| } |
| |
| // compareEntries compares most fields list of Entries against expected. compareEntries does not compare: |
| // - HTTPRequest |
| // - Operation |
| // - Resource |
| // - SourceLocation |
| func compareEntries(got, want []*logging.Entry) (string, bool) { |
| if len(got) != len(want) { |
| return fmt.Sprintf("got %d entries, want %d", len(got), len(want)), false |
| } |
| for i := range got { |
| if !compareEntry(got[i], want[i]) { |
| return fmt.Sprintf("#%d:\ngot %+v\nwant %+v", i, got[i], want[i]), false |
| } |
| } |
| return "", true |
| } |
| |
| func compareEntry(got, want *logging.Entry) bool { |
| if got.Timestamp.Unix() != want.Timestamp.Unix() { |
| return false |
| } |
| |
| if got.Severity != want.Severity { |
| return false |
| } |
| |
| if !ltesting.PayloadEqual(got.Payload, want.Payload) { |
| return false |
| } |
| if !testutil.Equal(got.Labels, want.Labels) { |
| return false |
| } |
| |
| if got.InsertID != want.InsertID { |
| return false |
| } |
| |
| if got.LogName != want.LogName { |
| return false |
| } |
| |
| return true |
| } |
| |
| func entryForTesting(payload interface{}) *logging.Entry { |
| return &logging.Entry{ |
| Timestamp: testNow().UTC(), |
| Payload: payload, |
| LogName: "projects/" + testProjectID + "/logs/" + testLogID, |
| Resource: &mrpb.MonitoredResource{Type: "global", Labels: map[string]string{"project_id": testProjectID}}, |
| } |
| } |
| |
| // allTestLogEntries should be called sparingly. It takes ~10s to get logs, even with indexed filters. |
| func allTestLogEntries(ctx context.Context) ([]*logging.Entry, error) { |
| return allEntries(ctx, aclient, testFilter) |
| } |
| |
| func allEntries(ctx context.Context, aclient *logadmin.Client, filter string) ([]*logging.Entry, error) { |
| var es []*logging.Entry |
| it := aclient.Entries(ctx, logadmin.Filter(filter)) |
| for { |
| e, err := cleanNext(it) |
| switch err { |
| case nil: |
| es = append(es, e) |
| case iterator.Done: |
| return es, nil |
| default: |
| return nil, err |
| } |
| } |
| } |
| |
| func cleanNext(it *logadmin.EntryIterator) (*logging.Entry, error) { |
| e, err := it.Next() |
| if err != nil { |
| return nil, err |
| } |
| clean(e) |
| return e, nil |
| } |
| |
| func TestStandardLogger(t *testing.T) { |
| initLogs() // Generate new testLogID |
| ctx := context.Background() |
| lg := client.Logger(testLogID) |
| slg := lg.StandardLogger(logging.Info) |
| |
| if slg != lg.StandardLogger(logging.Info) { |
| t.Error("There should be only one standard logger at each severity.") |
| } |
| if slg == lg.StandardLogger(logging.Debug) { |
| t.Error("There should be a different standard logger for each severity.") |
| } |
| |
| slg.Print("info") |
| if err := lg.Flush(); err != nil { |
| t.Fatal(err) |
| } |
| var got []*logging.Entry |
| ok := waitFor(func() bool { |
| var err error |
| got, err = allTestLogEntries(ctx) |
| if err != nil { |
| t.Log("fetching log entries: ", err) |
| return false |
| } |
| return len(got) == 1 |
| }) |
| if !ok { |
| t.Fatalf("timed out; got: %d, want: %d\n", len(got), 1) |
| } |
| if len(got) != 1 { |
| t.Fatalf("expected non-nil request with one entry; got:\n%+v", got) |
| } |
| if got, want := got[0].Payload.(string), "info\n"; got != want { |
| t.Errorf("payload: got %q, want %q", got, want) |
| } |
| if got, want := logging.Severity(got[0].Severity), logging.Info; got != want { |
| t.Errorf("severity: got %s, want %s", got, want) |
| } |
| } |
| |
| func TestStandardLoggerPopulateSourceLocation(t *testing.T) { |
| initLogs() // Generate new testLogID |
| ctx := context.Background() |
| lg := client.Logger(testLogID, logging.SourceLocationPopulation(logging.AlwaysPopulateSourceLocation)) |
| slg := lg.StandardLogger(logging.Info) |
| |
| _, _, line, lineOk := runtime.Caller(0) |
| if !lineOk { |
| t.Fatal("Cannot determine line number") |
| } |
| wantLine := int64(line + 5) |
| slg.Print("info") |
| if err := lg.Flush(); err != nil { |
| t.Fatal(err) |
| } |
| var got []*logging.Entry |
| ok := waitFor(func() bool { |
| var err error |
| got, err = allTestLogEntries(ctx) |
| if err != nil { |
| t.Log("fetching log entries: ", err) |
| return false |
| } |
| return len(got) == 1 |
| }) |
| if !ok { |
| t.Fatalf("timed out; got: %d, want: %d\n", len(got), 1) |
| } |
| if len(got) != 1 { |
| t.Fatalf("expected non-nil request with one entry; got:\n%+v", got) |
| } |
| if got, want := filepath.Base(got[0].SourceLocation.GetFile()), "logging_test.go"; got != want { |
| t.Errorf("sourcelocation file: got %s, want %s", got, want) |
| } |
| if got, want := got[0].SourceLocation.GetFunction(), "cloud.google.com/go/logging_test.TestStandardLoggerPopulateSourceLocation"; got != want { |
| t.Errorf("sourcelocation function: got %s, want %s", got, want) |
| } |
| if got := got[0].SourceLocation.Line; got != wantLine { |
| t.Errorf("source location line: got %d, want %d", got, wantLine) |
| } |
| } |
| |
| func TestStandardLoggerFromTemplate(t *testing.T) { |
| tests := []struct { |
| name string |
| template logging.Entry |
| message string |
| want logging.Entry |
| }{ |
| { |
| name: "severity only", |
| template: logging.Entry{ |
| Severity: logging.Error, |
| }, |
| message: "log message", |
| want: logging.Entry{ |
| Severity: logging.Error, |
| Payload: "log message\n", |
| }, |
| }, |
| { |
| name: "severity and trace", |
| template: logging.Entry{ |
| Severity: logging.Info, |
| Trace: "projects/P/traces/105445aa7843bc8bf206b120001000", |
| }, |
| message: "log message", |
| want: logging.Entry{ |
| Severity: logging.Info, |
| Payload: "log message\n", |
| Trace: "projects/P/traces/105445aa7843bc8bf206b120001000", |
| }, |
| }, |
| { |
| name: "severity and http request", |
| template: logging.Entry{ |
| Severity: logging.Info, |
| HTTPRequest: &logging.HTTPRequest{ |
| Request: &http.Request{ |
| Method: "GET", |
| Host: "example.com", |
| }, |
| Status: 200, |
| }, |
| }, |
| message: "log message", |
| want: logging.Entry{ |
| Severity: logging.Info, |
| Payload: "log message\n", |
| HTTPRequest: &logging.HTTPRequest{ |
| Request: &http.Request{ |
| Method: "GET", |
| Host: "example.com", |
| }, |
| Status: 200, |
| }, |
| }, |
| }, |
| { |
| name: "payload in template is ignored", |
| template: logging.Entry{ |
| Severity: logging.Info, |
| Payload: "this should not be set in the template", |
| Trace: "projects/P/traces/105445aa7843bc8bf206b120001000", |
| }, |
| message: "log message", |
| want: logging.Entry{ |
| Severity: logging.Info, |
| Payload: "log message\n", |
| Trace: "projects/P/traces/105445aa7843bc8bf206b120001000", |
| }, |
| }, |
| } |
| lg := client.Logger(testLogID) |
| for _, tc := range tests { |
| t.Run(tc.name, func(t *testing.T) { |
| mock := func(got logging.Entry, l *logging.Logger, parent string, skipLevels int) (*logpb.LogEntry, error) { |
| if !reflect.DeepEqual(got, tc.want) { |
| t.Errorf("Emitted Entry incorrect. Expected %v got %v", tc.want, got) |
| } |
| // Return value is not interesting |
| return &logpb.LogEntry{}, nil |
| } |
| |
| f := logging.SetToLogEntryInternal(mock) |
| defer func() { logging.SetToLogEntryInternal(f) }() |
| |
| slg := lg.StandardLoggerFromTemplate(&tc.template) |
| slg.Print(tc.message) |
| if err := lg.Flush(); err != nil { |
| t.Fatal(err) |
| } |
| }) |
| } |
| } |
| |
| func TestSeverity(t *testing.T) { |
| if got, want := logging.Info.String(), "Info"; got != want { |
| t.Errorf("got %q, want %q", got, want) |
| } |
| if got, want := logging.Severity(-99).String(), "-99"; got != want { |
| t.Errorf("got %q, want %q", got, want) |
| } |
| } |
| |
| func TestParseSeverity(t *testing.T) { |
| for _, test := range []struct { |
| in string |
| want logging.Severity |
| }{ |
| {"", logging.Default}, |
| {"whatever", logging.Default}, |
| {"Default", logging.Default}, |
| {"ERROR", logging.Error}, |
| {"Error", logging.Error}, |
| {"error", logging.Error}, |
| } { |
| got := logging.ParseSeverity(test.in) |
| if got != test.want { |
| t.Errorf("%q: got %s, want %s\n", test.in, got, test.want) |
| } |
| } |
| } |
| |
| func TestErrors(t *testing.T) { |
| initLogs() // Generate new testLogID |
| // Drain errors already seen. |
| loop: |
| for { |
| select { |
| case <-errorc: |
| default: |
| break loop |
| } |
| } |
| // Try to log something that can't be JSON-marshalled. |
| lg := client.Logger(testLogID) |
| lg.Log(logging.Entry{Payload: func() {}}) |
| // Expect an error from Flush. |
| err := lg.Flush() |
| if err == nil { |
| t.Fatal("expected error, got nil") |
| } |
| } |
| |
| type badTokenSource struct{} |
| |
| func (badTokenSource) Token() (*oauth2.Token, error) { |
| return &oauth2.Token{}, nil |
| } |
| |
| func TestPing(t *testing.T) { |
| // Ping twice, in case the service's InsertID logic messes with the error code. |
| ctx := context.Background() |
| // The global client should be valid. |
| if err := client.Ping(ctx); err != nil { |
| t.Errorf("project %s: got %v, expected nil", testProjectID, err) |
| } |
| if err := client.Ping(ctx); err != nil { |
| t.Errorf("project %s, #2: got %v, expected nil", testProjectID, err) |
| } |
| // nonexistent project |
| c, a := newClients(ctx, testProjectID+"-BAD") |
| defer c.Close() |
| defer a.Close() |
| if err := c.Ping(ctx); err == nil { |
| t.Errorf("nonexistent project: want error pinging logging api, got nil") |
| } |
| if err := c.Ping(ctx); err == nil { |
| t.Errorf("nonexistent project, #2: want error pinging logging api, got nil") |
| } |
| |
| // Bad creds. We cannot test this with the fake, since it doesn't do auth. |
| if integrationTest { |
| c, err := logging.NewClient(ctx, testProjectID, option.WithTokenSource(badTokenSource{})) |
| if err != nil { |
| t.Fatal(err) |
| } |
| if err := c.Ping(ctx); err == nil { |
| t.Errorf("bad creds: want error pinging logging api, got nil") |
| } |
| if err := c.Ping(ctx); err == nil { |
| t.Errorf("bad creds, #2: want error pinging logging api, got nil") |
| } |
| if err := c.Close(); err != nil { |
| t.Fatalf("error closing client: %v", err) |
| } |
| } |
| } |
| |
| func TestDeleteLog(t *testing.T) { |
| ctx := context.Background() |
| initLogs() |
| c, a := newClients(ctx, testProjectID) |
| defer c.Close() |
| defer a.Close() |
| lg := c.Logger(testLogID) |
| |
| if err := lg.LogSync(ctx, logging.Entry{Payload: "hello"}); err != nil { |
| t.Fatal(err) |
| } |
| |
| if err := aclient.DeleteLog(ctx, testLogID); err != nil { |
| // Ignore NotFound. Sometimes, amazingly, DeleteLog cannot find |
| // a log that is returned by Logs. |
| if status.Code(err) != codes.NotFound { |
| t.Fatalf("deleting %q: %v", testLogID, err) |
| } |
| } else { |
| t.Logf("deleted log_id: %q", testLogID) |
| } |
| } |
| |
| func TestNonProjectParent(t *testing.T) { |
| ctx := context.Background() |
| initLogs() |
| parent := "organizations/" + ltesting.ValidOrgID |
| c, a := newClients(ctx, parent) |
| defer c.Close() |
| defer a.Close() |
| lg := c.Logger(testLogID) |
| err := lg.LogSync(ctx, logging.Entry{Payload: "hello"}) |
| if integrationTest { |
| // We don't have permission to log to the organization. |
| if got, want := status.Code(err), codes.PermissionDenied; got != want { |
| t.Errorf("got code %s, want %s", got, want) |
| } |
| return |
| } |
| // Continue test against fake. |
| if err != nil { |
| t.Fatal(err) |
| } |
| want := []*logging.Entry{{ |
| Timestamp: testNow().UTC(), |
| Payload: "hello", |
| LogName: parent + "/logs/" + testLogID, |
| Resource: &mrpb.MonitoredResource{ |
| Type: "organization", |
| Labels: map[string]string{"organization_id": ltesting.ValidOrgID}, |
| }, |
| }} |
| var got []*logging.Entry |
| ok := waitFor(func() bool { |
| got, err = allEntries(ctx, a, fmt.Sprintf(`logName = "%s/logs/%s"`, parent, |
| strings.Replace(testLogID, "/", "%2F", -1))) |
| if err != nil { |
| t.Log("fetching log entries: ", err) |
| return false |
| } |
| return len(got) == len(want) |
| }) |
| if !ok { |
| t.Fatalf("timed out; got: %d, want: %d\n", len(got), len(want)) |
| } |
| if msg, ok := compareEntries(got, want); !ok { |
| t.Error(msg) |
| } |
| } |
| |
| func TestDetectProjectIdParent(t *testing.T) { |
| ctx := context.Background() |
| initLogs() |
| addr, err := ltesting.NewServer() |
| if err != nil { |
| t.Fatalf("creating fake server: %v", err) |
| } |
| conn, err := grpc.Dial(addr, grpc.WithInsecure()) |
| if err != nil { |
| t.Fatalf("dialing %q: %v", addr, err) |
| } |
| |
| tests := []struct { |
| name string |
| resource *mrpb.MonitoredResource |
| want string |
| wantError error |
| }{ |
| { |
| name: "Test DetectProjectId parent properly set up resource detection", |
| resource: &mrpb.MonitoredResource{ |
| Labels: map[string]string{"project_id": testProjectID}, |
| }, |
| want: "projects/" + testProjectID, |
| }, |
| { |
| name: "Test DetectProjectId parent no resource detected", |
| resource: nil, |
| wantError: errors.New("could not determine project ID from environment"), |
| }, |
| } |
| |
| for _, test := range tests { |
| t.Run(test.name, func(t *testing.T) { |
| // Check if toLogEntryInternal was called with the right parent |
| toLogEntryInternalMock := func(got logging.Entry, l *logging.Logger, parent string, skipLevels int) (*logpb.LogEntry, error) { |
| if parent != test.want { |
| t.Errorf("toLogEntryInternal called with wrong parent. got: %s want: %s", parent, test.want) |
| } |
| return &logpb.LogEntry{}, nil |
| } |
| |
| detectResourceMock := func() *mrpb.MonitoredResource { |
| return test.resource |
| } |
| |
| realToLogEntryInternal := logging.SetToLogEntryInternal(toLogEntryInternalMock) |
| defer func() { logging.SetToLogEntryInternal(realToLogEntryInternal) }() |
| |
| realDetectResourceInternal := logging.SetDetectResourceInternal(detectResourceMock) |
| defer func() { logging.SetDetectResourceInternal(realDetectResourceInternal) }() |
| |
| cli, err := logging.NewClient(ctx, logging.DetectProjectID, option.WithGRPCConn(conn)) |
| if err != nil && test.wantError == nil { |
| t.Fatalf("Unexpected error: %+v: %v", test.resource, err) |
| } |
| if err == nil && test.wantError != nil { |
| t.Fatalf("Error is expected: %+v: %v", test.resource, test.wantError) |
| } |
| if test.wantError != nil { |
| return |
| } |
| |
| cli.Logger(testLogID).LogSync(ctx, logging.Entry{Payload: "hello"}) |
| }) |
| } |
| } |
| |
| // waitFor calls f repeatedly with exponential backoff, blocking until it returns true. |
| // It returns false after a while (if it times out). |
| func waitFor(f func() bool) bool { |
| // TODO(shadams): Find a better way to deflake these tests. |
| ctx, cancel := context.WithTimeout(context.Background(), 10*time.Minute) |
| defer cancel() |
| err := cinternal.Retry(ctx, |
| gax.Backoff{Initial: time.Second, Multiplier: 2, Max: 30 * time.Second}, |
| func() (bool, error) { return f(), nil }) |
| return err == nil |
| } |
| |
| // Interleave a lot of Log and Flush calls, to induce race conditions. |
| // Run this test with: |
| // |
| // go test -run LogFlushRace -race -count 100 |
| func TestLogFlushRace(t *testing.T) { |
| initLogs() // Generate new testLogID |
| lg := client.Logger(testLogID, |
| logging.ConcurrentWriteLimit(5), // up to 5 concurrent log writes |
| logging.EntryCountThreshold(100)) // small bundle size to increase interleaving |
| var wgf, wgl sync.WaitGroup |
| donec := make(chan struct{}) |
| for i := 0; i < 10; i++ { |
| wgl.Add(1) |
| go func() { |
| defer wgl.Done() |
| for j := 0; j < 1e4; j++ { |
| lg.Log(logging.Entry{Payload: "the payload"}) |
| } |
| }() |
| } |
| for i := 0; i < 5; i++ { |
| wgf.Add(1) |
| go func() { |
| defer wgf.Done() |
| for { |
| select { |
| case <-donec: |
| return |
| case <-time.After(time.Duration(rand.Intn(5)) * time.Millisecond): |
| if err := lg.Flush(); err != nil { |
| t.Error(err) |
| } |
| } |
| } |
| }() |
| } |
| wgl.Wait() |
| close(donec) |
| wgf.Wait() |
| } |
| |
| // Test the throughput of concurrent writers. |
| func BenchmarkConcurrentWrites(b *testing.B) { |
| if !integrationTest { |
| b.Skip("only makes sense when running against production service") |
| } |
| for n := 1; n <= 32; n *= 2 { |
| b.Run(fmt.Sprint(n), func(b *testing.B) { |
| b.StopTimer() |
| lg := client.Logger(testLogID, logging.ConcurrentWriteLimit(n), logging.EntryCountThreshold(1000)) |
| const ( |
| nEntries = 1e5 |
| payload = "the quick brown fox jumps over the lazy dog" |
| ) |
| b.SetBytes(int64(nEntries * len(payload))) |
| b.StartTimer() |
| for i := 0; i < b.N; i++ { |
| for j := 0; j < nEntries; j++ { |
| lg.Log(logging.Entry{Payload: payload}) |
| } |
| if err := lg.Flush(); err != nil { |
| b.Fatal(err) |
| } |
| } |
| }) |
| } |
| } |
| |
| func TestSeverityUnmarshal(t *testing.T) { |
| j := []byte(`{"logName": "test-log","severity": "ERROR","payload": "test"}`) |
| var entry logging.Entry |
| err := json.Unmarshal(j, &entry) |
| if err != nil { |
| t.Fatalf("en.Unmarshal: %v", err) |
| } |
| if entry.Severity != logging.Error { |
| t.Fatalf("Severity: got %v, want %v", entry.Severity, logging.Error) |
| } |
| } |
| |
| func TestSeverityAsNumberUnmarshal(t *testing.T) { |
| j := []byte(fmt.Sprintf(`{"logName": "test-log","severity": %d, "payload": "test"}`, logging.Info)) |
| var entry logging.Entry |
| err := json.Unmarshal(j, &entry) |
| if err != nil { |
| t.Fatalf("en.Unmarshal: %v", err) |
| } |
| if entry.Severity != logging.Info { |
| t.Fatalf("Severity: got %v, want %v", entry.Severity, logging.Info) |
| } |
| } |
| |
| func TestSeverityMarshalThenUnmarshal(t *testing.T) { |
| entry := logging.Entry{Severity: logging.Warning, Payload: "test"} |
| j, err := json.Marshal(entry) |
| if err != nil { |
| t.Fatalf("en.Marshal: %v", err) |
| } |
| |
| var entryU logging.Entry |
| |
| err = json.Unmarshal(j, &entryU) |
| if err != nil { |
| t.Fatalf("en.Unmarshal: %v", err) |
| } |
| |
| if entryU.Severity != logging.Warning { |
| t.Fatalf("Severity: got %v, want %v", entryU.Severity, logging.Warning) |
| } |
| } |
| |
| func TestSourceLocationPopulation(t *testing.T) { |
| tests := []struct { |
| name string |
| logger *logging.Logger |
| in logging.Entry |
| want *logpb.LogEntrySourceLocation |
| }{ |
| { |
| name: "populate source location for debug entry when allowed", |
| logger: client.Logger("test-source-location", logging.SourceLocationPopulation(logging.PopulateSourceLocationForDebugEntries)), |
| in: logging.Entry{ |
| Severity: logging.Severity(logging.Debug), |
| }, |
| // want field will be patched to setup actual code line and function name |
| want: nil, |
| }, { |
| name: "populate source location for non-debug entry when allowed", |
| logger: client.Logger("test-source-location", logging.SourceLocationPopulation(logging.AlwaysPopulateSourceLocation)), |
| in: logging.Entry{ |
| Severity: logging.Severity(logging.Default), |
| }, |
| // want field will be patched to setup actual code line and function name |
| want: nil, |
| }, { |
| name: "do not populate source location for debug entry with source location", |
| logger: client.Logger("test-source-location", logging.SourceLocationPopulation(logging.PopulateSourceLocationForDebugEntries)), |
| in: logging.Entry{ |
| Severity: logging.Severity(logging.Debug), |
| SourceLocation: &logpb.LogEntrySourceLocation{ |
| File: "test_source_file.go", |
| Function: "testFunction", |
| Line: 65536, |
| }, |
| }, |
| want: &logpb.LogEntrySourceLocation{ |
| File: "test_source_file.go", |
| Function: "testFunction", |
| Line: 65536, |
| }, |
| }, { |
| name: "do not populate source location for non-debug entry when only allowed for debug", |
| logger: client.Logger("test-source-location", logging.SourceLocationPopulation(logging.PopulateSourceLocationForDebugEntries)), |
| in: logging.Entry{ |
| Severity: logging.Severity(logging.Info), |
| }, |
| want: nil, |
| }, { |
| name: "do not populate source location when not allowed for any", |
| logger: client.Logger("test-source-location", logging.SourceLocationPopulation(logging.DoNotPopulateSourceLocation)), |
| in: logging.Entry{ |
| Severity: logging.Severity(logging.Debug), |
| }, |
| want: nil, |
| }, { |
| name: "do not populate source location by default", |
| logger: client.Logger("test-source-location"), |
| in: logging.Entry{ |
| Severity: logging.Severity(logging.Debug), |
| }, |
| want: nil, |
| }, |
| } |
| |
| for index, tc := range tests { |
| t.Run(tc.name, func(t *testing.T) { |
| // patch first two want results to produce correct source info |
| if index < 2 { |
| pc, file, line, ok := runtime.Caller(0) |
| if !ok { |
| t.Fatalf("Unexpected error: %+v: failed to call runtime.Caller()", tc.in) |
| } |
| details := runtime.FuncForPC(pc) |
| tc.want = &logpb.LogEntrySourceLocation{ |
| File: file, |
| Function: details.Name(), |
| Line: int64(line + 11), // 11 code lines between runtime.Caller() and logging.ToLogEntry() |
| } |
| } |
| e, err := tc.logger.ToLogEntry(tc.in, "projects/P") |
| if err != nil { |
| t.Fatalf("Unexpected error: %+v: %v", tc.in, err) |
| } |
| |
| if e.SourceLocation != tc.want { |
| if diff := cmp.Diff(e.SourceLocation, tc.want, cmpopts.IgnoreUnexported(logpb.LogEntrySourceLocation{})); diff != "" { |
| t.Errorf("got(-),want(+):\n%s", diff) |
| } |
| } |
| }) |
| } |
| } |
| |
| func BenchmarkSourceLocationPopulation(b *testing.B) { |
| logger := *client.Logger("test-source-location", logging.SourceLocationPopulation(logging.PopulateSourceLocationForDebugEntries)) |
| tests := []struct { |
| name string |
| in logging.Entry |
| }{ |
| { |
| name: "with source location population", |
| in: logging.Entry{ |
| Severity: logging.Severity(logging.Debug), |
| }, |
| }, { |
| name: "without source location population", |
| in: logging.Entry{ |
| Severity: logging.Severity(logging.Info), |
| }, |
| }, |
| } |
| var err error |
| for _, tc := range tests { |
| b.Run(tc.name, func(b *testing.B) { |
| for n := 0; n < b.N; n++ { |
| _, err = logger.ToLogEntry(tc.in, "projects/P") |
| if err != nil { |
| b.Fatalf("Unexpected error: %+v: %v", tc.in, err) |
| } |
| } |
| }) |
| } |
| } |
| |
| // writeLogEntriesTestHandler is a fake Logging backend handler used to test partialSuccess option logic |
| type writeLogEntriesTestHandler struct { |
| logpb.UnimplementedLoggingServiceV2Server |
| hook func(*logpb.WriteLogEntriesRequest) |
| } |
| |
| func (f *writeLogEntriesTestHandler) WriteLogEntries(_ context.Context, e *logpb.WriteLogEntriesRequest) (*logpb.WriteLogEntriesResponse, error) { |
| if f.hook != nil { |
| f.hook(e) |
| } |
| return &logpb.WriteLogEntriesResponse{}, nil |
| } |
| |
| func fakeClient(parent string, writeLogEntryHandler func(e *logpb.WriteLogEntriesRequest), serverOptions ...grpc.ServerOption) (*logging.Client, error) { |
| // setup fake server |
| fakeBackend := &writeLogEntriesTestHandler{} |
| l, err := net.Listen("tcp", "localhost:0") |
| if err != nil { |
| return nil, err |
| } |
| gsrv := grpc.NewServer(serverOptions...) |
| logpb.RegisterLoggingServiceV2Server(gsrv, fakeBackend) |
| fakeServerAddr := l.Addr().String() |
| go func() { |
| if err := gsrv.Serve(l); err != nil { |
| panic(err) |
| } |
| }() |
| fakeBackend.hook = writeLogEntryHandler |
| ctx := context.Background() |
| client, _ := logging.NewClient(ctx, parent, option.WithEndpoint(fakeServerAddr), |
| option.WithoutAuthentication(), |
| option.WithGRPCDialOption(grpc.WithInsecure())) |
| return client, nil |
| } |
| |
| func TestPartialSuccessOption(t *testing.T) { |
| var logger *logging.Logger |
| var partialSuccess bool |
| |
| entry := logging.Entry{Payload: "payload string"} |
| tests := []struct { |
| name string |
| do func() |
| }{ |
| { |
| name: "use PartialSuccess with LogSync", |
| do: func() { |
| logger.LogSync(context.Background(), entry) |
| }, |
| }, |
| { |
| name: "use PartialSuccess with Log", |
| do: func() { |
| logger.Log(entry) |
| logger.Flush() |
| }, |
| }, |
| } |
| |
| // setup fake client |
| client, err := fakeClient("projects/test", func(e *logpb.WriteLogEntriesRequest) { |
| partialSuccess = e.PartialSuccess |
| }) |
| if err != nil { |
| t.Fatal(err) |
| } |
| defer client.Close() |
| logger = client.Logger("abc", logging.PartialSuccess()) |
| |
| for _, tc := range tests { |
| t.Run(tc.name, func(t *testing.T) { |
| partialSuccess = false |
| tc.do() |
| if !partialSuccess { |
| t.Fatal("e.PartialSuccess = false, want true") |
| } |
| }) |
| } |
| } |
| |
| func TestWriteLogEntriesSizeLimit(t *testing.T) { |
| // Test that logging too many large requests at once doesn't bump up |
| // against WriteLogEntriesRequest size limit |
| sizeLimit := 10485760 // 10MiB size limit |
| |
| // Create a fake client whose server can only handle messages of at most sizeLimit |
| client, err := fakeClient("projects/test", func(e *logpb.WriteLogEntriesRequest) {}, grpc.MaxRecvMsgSize(sizeLimit)) |
| if err != nil { |
| t.Fatal(err) |
| } |
| |
| client.OnError = func(e error) { |
| t.Fatalf(e.Error()) |
| } |
| |
| defer client.Close() |
| logger := client.Logger("test") |
| entry := logging.Entry{Payload: strings.Repeat("1", 250000)} |
| |
| for i := 0; i < 200; i++ { |
| logger.Log(entry) |
| } |
| } |
| |
| func TestRedirectOutputIngestion(t *testing.T) { |
| var hookCalled bool |
| |
| // setup fake client |
| client, err := fakeClient("projects/test", func(e *logpb.WriteLogEntriesRequest) { |
| hookCalled = true |
| }) |
| if err != nil { |
| t.Fatal(err) |
| } |
| defer client.Close() |
| |
| entry := logging.Entry{Payload: "testing payload string"} |
| tests := []struct { |
| name string |
| logger *logging.Logger |
| want bool |
| }{ |
| { |
| name: "redirect output does not ingest", |
| logger: client.Logger("stdout-redirection-log", logging.RedirectAsJSON(os.Stdout)), |
| want: false, |
| }, |
| { |
| name: "log without Redirect flags ingest", |
| logger: client.Logger("default-ingestion-log"), |
| want: true, |
| }, |
| } |
| for _, tc := range tests { |
| t.Run(tc.name, func(t *testing.T) { |
| hookCalled = false |
| tc.logger.LogSync(context.Background(), entry) |
| if hookCalled != tc.want { |
| t.Errorf("Log ingestion works unexpected: got %v want %v\n", hookCalled, tc.want) |
| } |
| }) |
| } |
| } |
| |
| func TestRedirectOutputFormats(t *testing.T) { |
| testURL, _ := url.Parse("https://example.com/test") |
| tests := []struct { |
| name string |
| in *logging.Entry |
| want string |
| wantError error |
| }{ |
| { |
| name: "full data redirect with text payload", |
| in: &logging.Entry{ |
| Labels: map[string]string{"key1": "value1", "key2": "value2"}, |
| Timestamp: testNow().UTC(), |
| Severity: logging.Debug, |
| InsertID: "0000AAA01", |
| Trace: "projects/P/ABCD12345678AB12345678", |
| SpanID: "000000000001", |
| TraceSampled: true, |
| SourceLocation: &logpb.LogEntrySourceLocation{ |
| File: "acme.go", |
| Function: "main", |
| Line: 100, |
| }, |
| Operation: &logpb.LogEntryOperation{ |
| Id: "0123456789", |
| Producer: "test", |
| }, |
| HTTPRequest: &logging.HTTPRequest{ |
| Request: &http.Request{ |
| URL: testURL, |
| Method: "POST", |
| }, |
| }, |
| |
| Payload: "this is text payload", |
| }, |
| want: `{"httpRequest":{"requestMethod":"POST","requestUrl":"https://example.com/test"},"logging.googleapis.com/insertId":"0000AAA01",` + |
| `"logging.googleapis.com/labels":{"key1":"value1","key2":"value2"},"logging.googleapis.com/operation":{"id":"0123456789","producer":"test"},` + |
| `"logging.googleapis.com/sourceLocation":{"file":"acme.go","function":"main","line":"100"},"logging.googleapis.com/spanId":"000000000001",` + |
| `"logging.googleapis.com/trace":"projects/P/ABCD12345678AB12345678","logging.googleapis.com/trace_sampled":true,` + |
| `"message":"this is text payload","severity":"DEBUG","timestamp":"seconds:1000"}`, |
| }, |
| { |
| name: "full data redirect with json payload", |
| in: &logging.Entry{ |
| Labels: map[string]string{"key1": "value1", "key2": "value2"}, |
| Timestamp: testNow().UTC(), |
| Severity: logging.Debug, |
| InsertID: "0000AAA01", |
| Trace: "projects/P/ABCD12345678AB12345678", |
| SpanID: "000000000001", |
| TraceSampled: true, |
| SourceLocation: &logpb.LogEntrySourceLocation{ |
| File: "acme.go", |
| Function: "main", |
| Line: 100, |
| }, |
| Operation: &logpb.LogEntryOperation{ |
| Id: "0123456789", |
| Producer: "test", |
| }, |
| HTTPRequest: &logging.HTTPRequest{ |
| Request: &http.Request{ |
| URL: testURL, |
| Method: "POST", |
| }, |
| }, |
| Payload: map[string]interface{}{ |
| "Message": "message part of the payload", |
| "Latency": 321, |
| }, |
| }, |
| want: `{"httpRequest":{"requestMethod":"POST","requestUrl":"https://example.com/test"},"logging.googleapis.com/insertId":"0000AAA01",` + |
| `"logging.googleapis.com/labels":{"key1":"value1","key2":"value2"},"logging.googleapis.com/operation":{"id":"0123456789","producer":"test"},` + |
| `"logging.googleapis.com/sourceLocation":{"file":"acme.go","function":"main","line":"100"},"logging.googleapis.com/spanId":"000000000001",` + |
| `"logging.googleapis.com/trace":"projects/P/ABCD12345678AB12345678","logging.googleapis.com/trace_sampled":true,` + |
| `"message":{"Latency":321,"Message":"message part of the payload"},"severity":"DEBUG","timestamp":"seconds:1000"}`, |
| }, |
| { |
| name: "error on redirect with proto payload", |
| in: &logging.Entry{ |
| Timestamp: testNow().UTC(), |
| Severity: logging.Debug, |
| Payload: &anypb.Any{}, |
| }, |
| wantError: logging.ErrRedirectProtoPayloadNotSupported, |
| }, |
| } |
| buffer := &strings.Builder{} |
| logger := client.Logger("test-redirect-output", logging.RedirectAsJSON(buffer)) |
| for _, tc := range tests { |
| t.Run(tc.name, func(t *testing.T) { |
| buffer.Reset() |
| err := logger.LogSync(context.Background(), *tc.in) |
| if err != nil { |
| if tc.wantError == nil { |
| t.Fatalf("Unexpected error: %+v: %v", tc.in, err) |
| } |
| if tc.wantError != err { |
| t.Errorf("Expected error: %+v, got: %v want: %v\n", tc.in, err, tc.wantError) |
| } |
| } else { |
| if tc.wantError != nil { |
| t.Errorf("Expected error: %+v, want: %v\n", tc.in, tc.wantError) |
| } |
| got := strings.TrimSpace(buffer.String()) |
| |
| // Compare structure equivalence of the outputs, not string equivalence, as order doesn't matter. |
| var gotJson, wantJson interface{} |
| |
| err = json.Unmarshal([]byte(got), &gotJson) |
| if err != nil { |
| t.Errorf("Error when serializing JSON output: %v", err) |
| } |
| |
| err = json.Unmarshal([]byte(tc.want), &wantJson) |
| if err != nil { |
| t.Fatalf("Error unmarshalling JSON input for want: %v", err) |
| } |
| |
| if !reflect.DeepEqual(gotJson, wantJson) { |
| t.Errorf("TestRedirectOutputFormats: %+v: got %v, want %v", tc.in, got, tc.want) |
| } |
| } |
| }) |
| } |
| } |
| |
| func TestInstrumentationIngestion(t *testing.T) { |
| var got []*logpb.LogEntry |
| |
| // setup fake client |
| client, err := fakeClient("projects/test", func(e *logpb.WriteLogEntriesRequest) { |
| got = e.GetEntries() |
| }) |
| if err != nil { |
| t.Fatal(err) |
| } |
| defer client.Close() |
| |
| entry := &logging.Entry{Severity: logging.Info, Payload: "test string"} |
| logger := client.Logger("test-instrumentation") |
| tests := []struct { |
| entryLen int |
| hasDiagnostic bool |
| }{ |
| { |
| entryLen: 2, |
| hasDiagnostic: true, |
| }, |
| { |
| entryLen: 1, |
| hasDiagnostic: false, |
| }, |
| } |
| onceBackup := internal.InstrumentOnce |
| internal.InstrumentOnce = new(sync.Once) |
| for _, test := range tests { |
| got = nil |
| err := logger.LogSync(context.Background(), *entry) |
| if err != nil { |
| t.Fatal(err) |
| } |
| if len(got) != test.entryLen { |
| t.Errorf("got(%v), want(%v)", got, test.entryLen) |
| } |
| diagnosticEntry := false |
| for _, ent := range got { |
| if internal.LogIDFromPath("projects/test", ent.LogName) == "diagnostic-log" { |
| diagnosticEntry = true |
| break |
| } |
| } |
| if diagnosticEntry != test.hasDiagnostic { |
| t.Errorf("instrumentation entry misplaced: got(%v), want(%v)", diagnosticEntry, test.hasDiagnostic) |
| } |
| } |
| internal.InstrumentOnce = onceBackup |
| } |
| |
| func TestInstrumentationWithRedirect(t *testing.T) { |
| want := []string{ |
| // do not format the string to preserve expected new-line between messages |
| `{"message":"test string","severity":"INFO","timestamp":"seconds:1000"} |
| {"message":{"logging.googleapis.com/diagnostic":{"instrumentation_source":[{"name":"go","version":"` + internal.Version + `"}],"runtime":"` + internal.VersionGo() + `"}},"severity":"DEFAULT","timestamp":"seconds:1000"}`, |
| `{"message":"test string","severity":"INFO","timestamp":"seconds:1000"}`, |
| } |
| entry := &logging.Entry{Severity: logging.Info, Payload: "test string"} |
| buffer := &strings.Builder{} |
| logger := client.Logger("test-redirect-output", logging.RedirectAsJSON(buffer)) |
| onceBackup, timeBackup := internal.InstrumentOnce, logging.SetNow(testNow) |
| internal.InstrumentOnce = new(sync.Once) |
| for i := range want { |
| buffer.Reset() |
| err := logger.LogSync(context.Background(), *entry) |
| if err != nil { |
| t.Fatal(err) |
| } |
| got := strings.TrimSpace(buffer.String()) |
| if got != want[i] { |
| t.Errorf("got(%v), want(%v)", got, want[i]) |
| } |
| } |
| logging.SetNow(timeBackup) |
| internal.InstrumentOnce = onceBackup |
| } |
| |
| func ExampleRedirectAsJSON_withStdout() { |
| logger := client.Logger("redirect-to-stdout", logging.RedirectAsJSON(os.Stdout)) |
| logger.Log(logging.Entry{Severity: logging.Debug, Payload: "redirected log"}) |
| } |