Line data    Source code

       1             : // Copyright 2019 The LevelDB-Go and Pebble Authors. All rights reserved. Use
       2             : // of this source code is governed by a BSD-style license that can be found in
       3             : // the LICENSE file.
       4             : 
       5             : package metamorphic
       6             : 
       7             : import (
       8             :         "fmt"
       9             :         "io"
      10             :         "log"
      11             :         "os"
      12             :         "regexp"
      13             :         "strconv"
      14             :         "strings"
      15             :         "sync"
      16             :         "sync/atomic"
      17             :         "time"
      18             :         "unicode"
      19             : 
      20             :         "github.com/cockroachdb/errors"
      21             :         "github.com/pmezard/go-difflib/difflib"
      22             :         "github.com/stretchr/testify/require"
      23             : )
      24             : 
      25             : // history records the results of running a series of operations.
      26             : //
      27             : // history also implements the pebble.Logger interface, outputting to a stdlib
      28             : // logger, prefixing the log messages with "//"-style comments.
      29             : type history struct {
      30             :         err    atomic.Value
      31             :         failRE *regexp.Regexp
      32             :         log    *log.Logger
      33             :         mu     struct {
      34             :                 sync.Mutex
      35             :                 closed bool
      36             :         }
      37             : }
      38             : 
      39           2 : func newHistory(failRE *regexp.Regexp, writers ...io.Writer) *history {
      40           2 :         h := &history{failRE: failRE}
      41           2 :         h.log = log.New(io.MultiWriter(writers...), "", 0)
      42           2 :         return h
      43           2 : }
      44             : 
      45           2 : func (h *history) Close() {
      46           2 :         h.mu.Lock()
      47           2 :         h.mu.closed = true
      48           2 :         h.mu.Unlock()
      49           2 : }
      50             : 
      51           2 : func (h *history) Recordf(op int, format string, args ...interface{}) {
      52           2 :         h.mu.Lock()
      53           2 :         defer h.mu.Unlock()
      54           2 :         if h.mu.closed {
      55           0 :                 panic("Recordf after close")
      56             :         }
      57           2 :         if strings.Contains(format, "\n") {
      58           0 :                 // We could remove this restriction but suffixing every line with "#<seq>".
      59           0 :                 panic(fmt.Sprintf("format string must not contain \\n: %q", format))
      60             :         }
      61             : 
      62             :         // We suffix every line with #<op> in order to provide a marker to locate
      63             :         // the line using the diff output. This is necessary because the diff of two
      64             :         // histories is done after stripping comment lines (`// ...`) from the
      65             :         // history output, which ruins the line number information in the diff
      66             :         // output.
      67           2 :         m := fmt.Sprintf(format, args...) + fmt.Sprintf(" #%d", op)
      68           2 :         h.log.Print(m)
      69           2 : 
      70           2 :         if h.failRE != nil && h.failRE.MatchString(m) {
      71           1 :                 err := errors.Errorf("failure regexp %q matched output: %s", h.failRE, m)
      72           1 :                 h.err.Store(err)
      73           1 :         }
      74             : }
      75             : 
      76             : // Error returns an error if the test has failed from log output, either a
      77             : // failure regexp match or a call to Fatalf.
      78           2 : func (h *history) Error() error {
      79           2 :         if v := h.err.Load(); v != nil {
      80           1 :                 return v.(error)
      81           1 :         }
      82           2 :         return nil
      83             : }
      84             : 
      85           2 : func (h *history) format(typ, format string, args ...interface{}) string {
      86           2 :         var buf strings.Builder
      87           2 :         orig := fmt.Sprintf(format, args...)
      88           2 :         timestamp := time.Now().Format("15:04:05.000")
      89           2 :         for _, line := range strings.Split(strings.TrimSpace(orig), "\n") {
      90           2 :                 fmt.Fprintf(&buf, "// %s %s: %s\n", timestamp, typ, line)
      91           2 :         }
      92           2 :         return buf.String()
      93             : }
      94             : 
      95             : // Infof implements the pebble.Logger interface. Note that the output is
      96             : // commented.
      97           2 : func (h *history) Infof(format string, args ...interface{}) {
      98           2 :         h.mu.Lock()
      99           2 :         defer h.mu.Unlock()
     100           2 :         // Suppress any messages that come after closing. This could happen if the
     101           2 :         // test doesn't close the database.
     102           2 :         if !h.mu.closed {
     103           2 :                 _ = h.log.Output(2, h.format("INFO", format, args...))
     104           2 :         }
     105             : }
     106             : 
     107             : // Errorf implements the pebble.Logger interface. Note that the output is
     108             : // commented.
     109           0 : func (h *history) Errorf(format string, args ...interface{}) {
     110           0 :         h.mu.Lock()
     111           0 :         defer h.mu.Unlock()
     112           0 :         // Suppress any messages that come after closing. This could happen if the
     113           0 :         // test doesn't close the database.
     114           0 :         if !h.mu.closed {
     115           0 :                 _ = h.log.Output(2, h.format("ERROR", format, args...))
     116           0 :         }
     117             : }
     118             : 
     119             : // Fatalf implements the pebble.Logger interface. Note that the output is
     120             : // commented.
     121           1 : func (h *history) Fatalf(format string, args ...interface{}) {
     122           1 :         h.mu.Lock()
     123           1 :         defer h.mu.Unlock()
     124           1 :         if h.mu.closed {
     125           0 :                 panic(fmt.Sprintf(format, args...))
     126             :         }
     127           1 :         _ = h.log.Output(2, h.format("FATAL", format, args...))
     128           1 :         // Store the first fatal error message.
     129           1 :         h.err.CompareAndSwap(nil, errors.Errorf(format, args...))
     130             : }
     131             : 
     132             : func (h *history) recorder(
     133             :         thread int, op int, optionalRecordf func(format string, args ...interface{}),
     134           2 : ) historyRecorder {
     135           2 :         return historyRecorder{
     136           2 :                 history:         h,
     137           2 :                 op:              op,
     138           2 :                 optionalRecordf: optionalRecordf,
     139           2 :         }
     140           2 : }
     141             : 
     142             : // historyRecorder pairs a history with an operation, annotating all lines
     143             : // recorded through it with the operation number.
     144             : type historyRecorder struct {
     145             :         history         *history
     146             :         op              int
     147             :         optionalRecordf func(string, ...interface{})
     148             : }
     149             : 
     150             : // Recordf records the results of a single operation.
     151           2 : func (h historyRecorder) Recordf(format string, args ...interface{}) {
     152           2 :         // Check for assertion errors.
     153           2 :         for _, a := range args {
     154           2 :                 if err, ok := a.(error); ok && errors.IsAssertionFailure(err) {
     155           0 :                         fmt.Fprintf(os.Stderr, "%+v", err)
     156           0 :                         panic(err)
     157             :                 }
     158             :         }
     159           2 :         h.history.Recordf(h.op, format, args...)
     160           2 :         // If the history recorder was configured with an additional record func,
     161           2 :         // invoke it. This can be used to collect the per-operation output when
     162           2 :         // manually stepping the metamorphic test.
     163           2 :         if h.optionalRecordf != nil {
     164           1 :                 h.optionalRecordf(format, args...)
     165           1 :         }
     166             : }
     167             : 
     168             : // Error returns an error if the test has failed from log output, either a
     169             : // failure regexp match or a call to Fatalf.
     170           0 : func (h historyRecorder) Error() error {
     171           0 :         return h.history.Error()
     172           0 : }
     173             : 
     174             : // CompareHistories takes a slice of file paths containing history files. It
     175             : // performs a diff comparing the first path to all other paths. CompareHistories
     176             : // returns the index and diff for the first history that differs. If all the
     177             : // histories are identical, CompareHistories returns a zero index and an empty
     178             : // string.
     179           0 : func CompareHistories(t TestingT, paths []string) (i int, diff string) {
     180           0 :         base := readHistory(t, paths[0])
     181           0 :         base = reorderHistory(base)
     182           0 : 
     183           0 :         for i := 1; i < len(paths); i++ {
     184           0 :                 lines := readHistory(t, paths[i])
     185           0 :                 lines = reorderHistory(lines)
     186           0 :                 diff := difflib.UnifiedDiff{
     187           0 :                         A:       base,
     188           0 :                         B:       lines,
     189           0 :                         Context: 5,
     190           0 :                 }
     191           0 :                 text, err := difflib.GetUnifiedDiffString(diff)
     192           0 :                 require.NoError(t, err)
     193           0 :                 if text != "" {
     194           0 :                         return i, text
     195           0 :                 }
     196             :         }
     197           0 :         return 0, ""
     198             : }
     199             : 
     200             : // reorderHistory takes lines from a history file and reorders the operation
     201             : // results to be in the order of the operation index numbers. Runs with more
     202             : // than 1 thread may produce out-of-order histories. Comment lines must've
     203             : // already been filtered out.
     204           1 : func reorderHistory(lines []string) []string {
     205           1 :         reordered := make([]string, len(lines))
     206           1 :         for _, l := range lines {
     207           1 :                 if cleaned := strings.TrimSpace(l); cleaned == "" {
     208           1 :                         continue
     209             :                 }
     210           1 :                 idx := extractOp(l)
     211           1 :                 if idx >= len(reordered) {
     212           0 :                         panic("incomplete test history; this shouldn't happen given that execution completed successfully")
     213             :                 }
     214           1 :                 reordered[idx] = l
     215             :         }
     216           1 :         return reordered
     217             : }
     218             : 
     219             : // extractOp parses out an operation's index from the trailing comment. Every
     220             : // line of history output is suffixed with a comment containing `#<op>`
     221           1 : func extractOp(line string) int {
     222           1 :         i := strings.LastIndexByte(line, '#')
     223           1 :         j := strings.IndexFunc(line[i+1:], unicode.IsSpace)
     224           1 :         if j == -1 {
     225           0 :                 j = len(line[i+1:])
     226           0 :         }
     227           1 :         v, err := strconv.Atoi(line[i+1 : i+1+j])
     228           1 :         if err != nil {
     229           0 :                 panic(fmt.Sprintf("unable to parse line %q: %s", line, err))
     230             :         }
     231           1 :         return v
     232             : }
     233             : 
     234             : // Read a history file, stripping out lines that begin with a comment.
     235           1 : func readHistory(t TestingT, historyPath string) []string {
     236           1 :         data, err := os.ReadFile(historyPath)
     237           1 :         require.NoError(t, err)
     238           1 :         lines := difflib.SplitLines(string(data))
     239           1 :         newLines := make([]string, 0, len(lines))
     240           1 :         for _, line := range lines {
     241           1 :                 if strings.HasPrefix(line, "// ") {
     242           1 :                         continue
     243             :                 }
     244           1 :                 newLines = append(newLines, line)
     245             :         }
     246           1 :         return newLines
     247             : }