main.go

Documentation: github.com/letsencrypt/boulder/cmd/caa-log-checker

     1  package notmain
     2  
     3  import (
     4  	"bufio"
     5  	"compress/gzip"
     6  	"encoding/json"
     7  	"errors"
     8  	"flag"
     9  	"fmt"
    10  	"io"
    11  	"os"
    12  	"regexp"
    13  	"strings"
    14  	"time"
    15  
    16  	"github.com/letsencrypt/boulder/cmd"
    17  	blog "github.com/letsencrypt/boulder/log"
    18  )
    19  
    20  var raIssuanceLineRE = regexp.MustCompile(`Certificate request - successful JSON=(.*)`)
    21  
    22  // TODO: Extract the "Valid for issuance: (true|false)" field too.
    23  var vaCAALineRE = regexp.MustCompile(`Checked CAA records for ([a-z0-9-.*]+), \[Present: (true|false)`)
    24  
    25  type issuanceEvent struct {
    26  	SerialNumber string
    27  	Names        []string
    28  	Requester    int64
    29  
    30  	issuanceTime time.Time
    31  }
    32  
    33  func openFile(path string) (*bufio.Scanner, error) {
    34  	f, err := os.Open(path)
    35  	if err != nil {
    36  		return nil, err
    37  	}
    38  	var reader io.Reader
    39  	reader = f
    40  	if strings.HasSuffix(path, ".gz") {
    41  		reader, err = gzip.NewReader(f)
    42  		if err != nil {
    43  			return nil, err
    44  		}
    45  	}
    46  	scanner := bufio.NewScanner(reader)
    47  	return scanner, nil
    48  }
    49  
    50  func parseTimestamp(line []byte) (time.Time, error) {
    51  	datestamp, err := time.Parse(time.RFC3339, string(line[0:32]))
    52  	if err != nil {
    53  		return time.Time{}, err
    54  	}
    55  	return datestamp, nil
    56  }
    57  
    58  // loadIssuanceLog processes a single issuance (RA) log file. It returns a map
    59  // of names to slices of timestamps at which certificates for those names were
    60  // issued. It also returns the earliest and latest timestamps seen, to allow
    61  // CAA log processing to quickly skip irrelevant entries.
    62  func loadIssuanceLog(path string) (map[string][]time.Time, time.Time, time.Time, error) {
    63  	scanner, err := openFile(path)
    64  	if err != nil {
    65  		return nil, time.Time{}, time.Time{}, fmt.Errorf("failed to open %q: %w", path, err)
    66  	}
    67  
    68  	linesCount := 0
    69  	earliest := time.Time{}
    70  	latest := time.Time{}
    71  
    72  	issuanceMap := map[string][]time.Time{}
    73  	for scanner.Scan() {
    74  		line := scanner.Bytes()
    75  		linesCount++
    76  
    77  		matches := raIssuanceLineRE.FindSubmatch(line)
    78  		if matches == nil {
    79  			continue
    80  		}
    81  		if len(matches) != 2 {
    82  			return nil, earliest, latest, fmt.Errorf("line %d: unexpected number of regex matches", linesCount)
    83  		}
    84  
    85  		var ie issuanceEvent
    86  		err := json.Unmarshal(matches[1], &ie)
    87  		if err != nil {
    88  			return nil, earliest, latest, fmt.Errorf("line %d: failed to unmarshal JSON: %w", linesCount, err)
    89  		}
    90  
    91  		// Populate the issuance time from the syslog timestamp, rather than the
    92  		// ResponseTime member of the JSON. This makes testing a lot simpler because
    93  		// of how we mess with time sometimes. Given that these timestamps are
    94  		// generated on the same system, they should be tightly coupled anyway.
    95  		ie.issuanceTime, err = parseTimestamp(line)
    96  		if err != nil {
    97  			return nil, earliest, latest, fmt.Errorf("line %d: failed to parse timestamp: %w", linesCount, err)
    98  		}
    99  
   100  		if earliest.IsZero() || ie.issuanceTime.Before(earliest) {
   101  			earliest = ie.issuanceTime
   102  		}
   103  		if latest.IsZero() || ie.issuanceTime.After(latest) {
   104  			latest = ie.issuanceTime
   105  		}
   106  		for _, name := range ie.Names {
   107  			issuanceMap[name] = append(issuanceMap[name], ie.issuanceTime)
   108  		}
   109  	}
   110  	err = scanner.Err()
   111  	if err != nil {
   112  		return nil, earliest, latest, err
   113  	}
   114  
   115  	return issuanceMap, earliest, latest, nil
   116  }
   117  
   118  // processCAALog processes a single CAA (VA) log file. It modifies the input map
   119  // (of issuance names to times, as returned by `loadIssuanceLog`) to remove any
   120  // timestamps which are covered by (i.e. less than 8 hours after) a CAA check
   121  // for that name in the log file. It also prunes any names whose slice of
   122  // issuance times becomes empty.
   123  func processCAALog(path string, issuances map[string][]time.Time, earliest time.Time, latest time.Time, tolerance time.Duration) error {
   124  	scanner, err := openFile(path)
   125  	if err != nil {
   126  		return fmt.Errorf("failed to open %q: %w", path, err)
   127  	}
   128  
   129  	linesCount := 0
   130  
   131  	for scanner.Scan() {
   132  		line := scanner.Bytes()
   133  		linesCount++
   134  
   135  		matches := vaCAALineRE.FindSubmatch(line)
   136  		if matches == nil {
   137  			continue
   138  		}
   139  		if len(matches) != 3 {
   140  			return fmt.Errorf("line %d: unexpected number of regex matches", linesCount)
   141  		}
   142  		name := string(matches[1])
   143  		present := string(matches[2])
   144  
   145  		checkTime, err := parseTimestamp(line)
   146  		if err != nil {
   147  			return fmt.Errorf("line %d: failed to parse timestamp: %w", linesCount, err)
   148  		}
   149  
   150  		// Don't bother processing rows that definitely fall outside the period we
   151  		// care about.
   152  		if checkTime.After(latest) || checkTime.Before(earliest.Add(-8*time.Hour)) {
   153  			continue
   154  		}
   155  
   156  		// TODO: Only remove covered issuance timestamps if the CAA check actually
   157  		// said that we're allowed to issue (i.e. had "Valid for issuance: true").
   158  		issuances[name] = removeCoveredTimestamps(issuances[name], checkTime, tolerance)
   159  		if len(issuances[name]) == 0 {
   160  			delete(issuances, name)
   161  		}
   162  
   163  		// If the CAA check didn't find any CAA records for w.x.y.z, then that means
   164  		// that we checked the CAA records for x.y.z, y.z, and z as well, and are
   165  		// covered for any issuance for those names.
   166  		if present == "false" {
   167  			labels := strings.Split(name, ".")
   168  			for i := 1; i < len(labels)-1; i++ {
   169  				tailName := strings.Join(labels[i:], ".")
   170  				issuances[tailName] = removeCoveredTimestamps(issuances[tailName], checkTime, tolerance)
   171  				if len(issuances[tailName]) == 0 {
   172  					delete(issuances, tailName)
   173  				}
   174  			}
   175  		}
   176  	}
   177  
   178  	return scanner.Err()
   179  }
   180  
   181  // removeCoveredTimestamps returns a new slice of timestamps which contains all
   182  // timestamps that are *not* within 8 hours after the input timestamp.
   183  func removeCoveredTimestamps(timestamps []time.Time, cover time.Time, tolerance time.Duration) []time.Time {
   184  	r := make([]time.Time, 0)
   185  	for _, ts := range timestamps {
   186  		// Copy the timestamp into the results slice if it is before the covering
   187  		// timestamp, or more than 8 hours after the covering timestamp (i.e. if
   188  		// it is *not* covered by the covering timestamp).
   189  		diff := ts.Sub(cover)
   190  		if diff < -tolerance || diff > 8*time.Hour+tolerance {
   191  			ts := ts
   192  			r = append(r, ts)
   193  		}
   194  	}
   195  	return r
   196  }
   197  
   198  // emitErrors returns nil if the input map is empty. Otherwise, it logs
   199  // a line for each name and issuance time that was not covered by a CAA
   200  // check, and return an error.
   201  func emitErrors(log blog.Logger, remaining map[string][]time.Time) error {
   202  	if len(remaining) == 0 {
   203  		return nil
   204  	}
   205  
   206  	for name, timestamps := range remaining {
   207  		for _, timestamp := range timestamps {
   208  			log.Infof("CAA-checking log event not found for issuance of %s at %s", name, timestamp)
   209  		}
   210  	}
   211  
   212  	return errors.New("Some CAA-checking log events not found")
   213  }
   214  
   215  func main() {
   216  	logStdoutLevel := flag.Int("stdout-level", 6, "Minimum severity of messages to send to stdout")
   217  	logSyslogLevel := flag.Int("syslog-level", 6, "Minimum severity of messages to send to syslog")
   218  	raLog := flag.String("ra-log", "", "Path to a single boulder-ra log file")
   219  	vaLogs := flag.String("va-logs", "", "List of paths to boulder-va logs, separated by commas")
   220  	timeTolerance := flag.Duration("time-tolerance", 0, "How much slop to allow when comparing timestamps for ordering")
   221  	earliestFlag := flag.String("earliest", "", "Deprecated.")
   222  	latestFlag := flag.String("latest", "", "Deprecated.")
   223  
   224  	flag.Parse()
   225  
   226  	logger := cmd.NewLogger(cmd.SyslogConfig{
   227  		StdoutLevel: *logStdoutLevel,
   228  		SyslogLevel: *logSyslogLevel,
   229  	})
   230  	logger.Info(cmd.VersionString())
   231  
   232  	if *timeTolerance < 0 {
   233  		cmd.Fail("value of -time-tolerance must be non-negative")
   234  	}
   235  
   236  	if *earliestFlag != "" || *latestFlag != "" {
   237  		logger.Info("The -earliest and -latest flags are deprecated and ignored.")
   238  	}
   239  
   240  	// Build a map from hostnames to times at which those names were issued for.
   241  	// Also retrieve the earliest and latest issuance times represented in the
   242  	// data, so we can be more efficient when examining entries from the CAA log.
   243  	issuanceMap, earliest, latest, err := loadIssuanceLog(*raLog)
   244  	cmd.FailOnError(err, "failed to load issuance logs")
   245  
   246  	// Try to pare the issuance map down to nothing by removing every entry which
   247  	// is covered by a CAA check.
   248  	for _, vaLog := range strings.Split(*vaLogs, ",") {
   249  		err = processCAALog(vaLog, issuanceMap, earliest, latest, *timeTolerance)
   250  		cmd.FailOnError(err, "failed to process CAA checking logs")
   251  	}
   252  
   253  	err = emitErrors(logger, issuanceMap)
   254  	if err != nil {
   255  		logger.AuditErrf("%s", err)
   256  		os.Exit(1)
   257  	}
   258  }
   259  
   260  func init() {
   261  	cmd.RegisterCommand("caa-log-checker", main, nil)
   262  }
   263
View as plain text