go.chromium.org/luci@v0.0.0-20240309015107-7cdc2e660f33/cv/internal/common/errors_test.go (about)

     1  // Copyright 2020 The LUCI Authors.
     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  package common
    16  
    17  import (
    18  	"context"
    19  	"testing"
    20  
    21  	"google.golang.org/grpc/codes"
    22  	"google.golang.org/grpc/status"
    23  
    24  	"go.chromium.org/luci/common/errors"
    25  	"go.chromium.org/luci/common/logging"
    26  	"go.chromium.org/luci/common/logging/gologger"
    27  	"go.chromium.org/luci/common/logging/memlogger"
    28  	"go.chromium.org/luci/common/logging/teelogger"
    29  	"go.chromium.org/luci/common/retry/transient"
    30  	"go.chromium.org/luci/server/tq"
    31  
    32  	. "github.com/smartystreets/goconvey/convey"
    33  )
    34  
    35  func TestTQifyError(t *testing.T) {
    36  	t.Parallel()
    37  
    38  	Convey("TQify works", t, func() {
    39  		ctx := memlogger.Use(context.Background())
    40  		ml := logging.Get(ctx).(*memlogger.MemLogger)
    41  		if testing.Verbose() {
    42  			// Write Debug log to both memlogger and gologger.
    43  			ctx = teelogger.Use(ctx, gologger.StdConfig.NewLogger)
    44  		}
    45  		ctx = logging.SetLevel(ctx, logging.Debug)
    46  
    47  		assertLoggedStack := func() {
    48  			So(ml.Messages(), ShouldHaveLength, 1)
    49  			m := ml.Messages()[0]
    50  			So(m.Level, ShouldEqual, logging.Error)
    51  			So(m.Msg, ShouldContainSubstring, "common.TestTQifyError()")
    52  			So(m.Msg, ShouldContainSubstring, "errors_test.go")
    53  		}
    54  		assertLoggedAt := func(level logging.Level) {
    55  			So(ml.Messages(), ShouldHaveLength, 1)
    56  			m := ml.Messages()[0]
    57  			So(m.Level, ShouldEqual, level)
    58  			So(m.Msg, ShouldNotContainSubstring, "errors_test.go")
    59  		}
    60  
    61  		errOops := errors.New("oops")
    62  		errBoo := errors.New("boo")
    63  		errTransBoo := transient.Tag.Apply(errBoo)
    64  		errWrapOops := errors.Annotate(errOops, "wrapped").Err()
    65  		errMulti := errors.NewMultiError(errWrapOops, errBoo)
    66  		errRare := errors.New("an oppressed invertebrate lacking emoji unlike 🐞 or 🐛")
    67  		errTransRare := transient.Tag.Apply(errRare)
    68  
    69  		Convey("matchesErrors is true if it matches ANY leaf errors", func() {
    70  			So(matchesErrors(errWrapOops, errOops), ShouldBeTrue)
    71  			So(matchesErrors(errMulti, errOops), ShouldBeTrue)
    72  
    73  			So(matchesErrors(errTransRare, errOops, errBoo, errRare), ShouldBeTrue)
    74  			So(matchesErrors(errTransRare, errOops, errBoo), ShouldBeFalse)
    75  		})
    76  
    77  		Convey("matchesErrors panics for invalid knownErrs", func() {
    78  			So(func() { matchesErrors(errOops, errMulti) }, ShouldPanic)
    79  			So(func() { matchesErrors(errOops, errWrapOops) }, ShouldPanic)
    80  		})
    81  
    82  		Convey("Simple", func() {
    83  			Convey("noop", func() {
    84  				err := TQifyError(ctx, nil)
    85  				So(err, ShouldBeNil)
    86  				So(ml.Messages(), ShouldHaveLength, 0)
    87  			})
    88  			Convey("non-transient becomes Fatal and is logged", func() {
    89  				err := TQifyError(ctx, errOops)
    90  				So(tq.Fatal.In(err), ShouldBeTrue)
    91  				So(tq.Ignore.In(err), ShouldBeFalse)
    92  				assertLoggedStack()
    93  			})
    94  			Convey("transient is retried and logged", func() {
    95  				err := TQifyError(ctx, errTransBoo)
    96  				So(tq.Fatal.In(err), ShouldBeFalse)
    97  				So(tq.Ignore.In(err), ShouldBeFalse)
    98  				assertLoggedStack()
    99  			})
   100  			Convey("with NeverRetry set", func() {
   101  				Convey("non-transient is still Fatal and logged", func() {
   102  					err := TQIfy{NeverRetry: true}.Error(ctx, errOops)
   103  					So(tq.Fatal.In(err), ShouldBeTrue)
   104  					So(tq.Ignore.In(err), ShouldBeFalse)
   105  					assertLoggedStack()
   106  				})
   107  				Convey("transient is not retried but logged", func() {
   108  					err := TQIfy{NeverRetry: true}.Error(ctx, errTransBoo)
   109  					So(tq.Ignore.In(err), ShouldBeTrue)
   110  					So(tq.Fatal.In(err), ShouldBeFalse)
   111  					assertLoggedStack()
   112  				})
   113  			})
   114  		})
   115  
   116  		Convey("With Known errors", func() {
   117  			errRetryTag := errors.BoolTag{
   118  				Key: errors.NewTagKey("this error should be retried"),
   119  			}
   120  			errIgnoreTag := errors.BoolTag{
   121  				Key: errors.NewTagKey("this error should be ignored"),
   122  			}
   123  			tqify := TQIfy{
   124  				KnownRetry:      []error{errBoo},
   125  				KnownRetryTags:  []errors.BoolTag{errRetryTag},
   126  				KnownIgnore:     []error{errOops},
   127  				KnownIgnoreTags: []errors.BoolTag{errIgnoreTag},
   128  			}
   129  			Convey("on unknown error", func() {
   130  				Convey("transient -> retry and log entire stack", func() {
   131  					err := tqify.Error(ctx, errTransRare)
   132  					So(tq.Fatal.In(err), ShouldBeFalse)
   133  					assertLoggedStack()
   134  				})
   135  				Convey("non-transient -> tq.Fatal", func() {
   136  					err := tqify.Error(ctx, errRare)
   137  					So(tq.Fatal.In(err), ShouldBeTrue)
   138  					assertLoggedStack()
   139  				})
   140  			})
   141  
   142  			Convey("KnownIgnore => tq.Ignore, log as warning", func() {
   143  				err := tqify.Error(ctx, errWrapOops)
   144  				So(tq.Ignore.In(err), ShouldBeTrue)
   145  				So(tq.Fatal.In(err), ShouldBeFalse)
   146  				assertLoggedAt(logging.Warning)
   147  			})
   148  			Convey("KnownIgnoreTags => tq.Ignore, log as warning", func() {
   149  				err := tqify.Error(ctx, errIgnoreTag.Apply(errRare))
   150  				So(tq.Ignore.In(err), ShouldBeTrue)
   151  				So(tq.Fatal.In(err), ShouldBeFalse)
   152  				assertLoggedAt(logging.Warning)
   153  			})
   154  			Convey("KnownRetry => non-transient, non-Fatal, log as warning", func() {
   155  				err := tqify.Error(ctx, errTransBoo)
   156  				So(tq.Fatal.In(err), ShouldBeFalse)
   157  				So(transient.Tag.In(err), ShouldBeFalse)
   158  				assertLoggedAt(logging.Warning)
   159  			})
   160  			Convey("KnownRetryTags => non-transient, non-Fatal, log as warning", func() {
   161  				err := tqify.Error(ctx, errRetryTag.Apply(errRare))
   162  				So(tq.Fatal.In(err), ShouldBeFalse)
   163  				So(transient.Tag.In(err), ShouldBeFalse)
   164  				assertLoggedAt(logging.Warning)
   165  			})
   166  			Convey("KnownRetry & KnownIgnore => KnownRetry wins, log about a BUG", func() {
   167  				err := tqify.Error(ctx, errMulti)
   168  				So(tq.Fatal.In(err), ShouldBeFalse)
   169  				So(transient.Tag.In(err), ShouldBeFalse)
   170  				So(ml.Messages(), ShouldHaveLength, 2)
   171  				So(ml.Messages()[0].Level, ShouldEqual, logging.Error)
   172  				So(ml.Messages()[0].Msg, ShouldContainSubstring, "BUG: invalid TQIfy config")
   173  				So(ml.Messages()[1].Level, ShouldEqual, logging.Warning)
   174  				So(ml.Messages()[1].Msg, ShouldContainSubstring, errMulti.Error())
   175  			})
   176  
   177  			Convey("Panic if KnownRetry is used with with NeverRetry", func() {
   178  				tqify = TQIfy{
   179  					KnownRetry: []error{errBoo},
   180  					NeverRetry: true,
   181  				}
   182  				So(func() { tqify.Error(ctx, errBoo) }, ShouldPanic)
   183  			})
   184  			Convey("Panic if KnownRetryTag is used with with NeverRetry", func() {
   185  				tqify = TQIfy{
   186  					KnownRetryTags: []errors.BoolTag{errRetryTag},
   187  					NeverRetry:     true,
   188  				}
   189  				So(func() { tqify.Error(ctx, errRetryTag.Apply(errRare)) }, ShouldPanic)
   190  			})
   191  		})
   192  	})
   193  }
   194  
   195  func TestMostSevereError(t *testing.T) {
   196  	t.Parallel()
   197  
   198  	Convey("MostSevereError works", t, func() {
   199  		// fatal means non-transient here.
   200  		fatal1 := errors.New("fatal1")
   201  		fatal2 := errors.New("fatal2")
   202  		trans1 := errors.New("trans1", transient.Tag)
   203  		trans2 := errors.New("trans2", transient.Tag)
   204  		multFatal := errors.NewMultiError(trans1, nil, fatal1, fatal2)
   205  		multTrans := errors.NewMultiError(nil, trans1, nil, trans2, nil)
   206  		tensor := errors.NewMultiError(nil, errors.NewMultiError(nil, multTrans, multFatal))
   207  
   208  		So(MostSevereError(nil), ShouldBeNil)
   209  		So(MostSevereError(fatal1), ShouldEqual, fatal1)
   210  		So(MostSevereError(trans1), ShouldEqual, trans1)
   211  
   212  		So(MostSevereError(multFatal), ShouldEqual, fatal1)
   213  		So(MostSevereError(multTrans), ShouldEqual, trans1)
   214  		So(MostSevereError(tensor), ShouldEqual, fatal1)
   215  	})
   216  }
   217  
   218  func TestIsDatastoreContention(t *testing.T) {
   219  	t.Parallel()
   220  
   221  	Convey("IsDatastoreContention works", t, func() {
   222  		// fatal means non-transient here.
   223  		So(IsDatastoreContention(errors.New("fatal1")), ShouldBeFalse)
   224  		// This is copied from what was actually observed in prod as of 2021-07-22.
   225  		err := status.Errorf(codes.Aborted, "Aborted due to cross-transaction contention. This occurs when multiple transactions attempt to access the same data, requiring Firestore to abort at least one in order to enforce serializability")
   226  		So(IsDatastoreContention(err), ShouldBeTrue)
   227  		So(IsDatastoreContention(errors.Annotate(err, "wrapped").Err()), ShouldBeTrue)
   228  	})
   229  }