cmd/caa-log-checker: -earliest and -latest (#5045)
Since we now sync caaChecks logs daily instead of continuously, caa-log-checker can no longer assume that the validation logs it is checking cover the exact same span of time as the issuance logs. This commit adds -earliest and -latest parameters so that the script that drives this tool can restrict verification to a timespan where we know the data is valid. Also adds a -debug flag to caa-log-checker to enable debug logs. At the moment this makes the tool write to stderr how many issuance messages were evaluated and how many were skipped due to -earliest and -latest parameters.
This commit is contained in:
Tim Geoghegan
GitHub
parent
30ebb2427c
commit
8685e7aec2
|
|
@ -16,6 +16,8 @@ import (
|
|||
"github.com/letsencrypt/boulder/cmd"
|
||||
)
|
||||
|
||||
var debug = flag.Bool("debug", false, "Enable debug logging")
|
||||
|
||||
func openFile(path string) (*bufio.Scanner, error) {
|
||||
f, err := os.Open(path)
|
||||
if err != nil {
|
||||
|
|
@ -52,22 +54,25 @@ func parseTimestamp(line string) (time.Time, error) {
|
|||
return datestamp, nil
|
||||
}
|
||||
|
||||
func checkIssuances(scanner *bufio.Scanner, checkedMap map[string][]time.Time, timeTolerance time.Duration, stderr *os.File) error {
|
||||
lNum := 0
|
||||
func checkIssuances(scanner *bufio.Scanner, checkedMap map[string][]time.Time, timeTolerance time.Duration,
|
||||
earliest time.Time, latest time.Time, stderr *os.File) error {
|
||||
linesRead := 0
|
||||
skipCount := 0
|
||||
evaluatedCount := 0
|
||||
for scanner.Scan() {
|
||||
lNum++
|
||||
linesRead++
|
||||
line := scanner.Text()
|
||||
matches := raIssuanceLineRE.FindStringSubmatch(line)
|
||||
if matches == nil {
|
||||
continue
|
||||
}
|
||||
if len(matches) != 2 {
|
||||
return fmt.Errorf("line %d: unexpected number of regex matches", lNum)
|
||||
return fmt.Errorf("line %d: unexpected number of regex matches", linesRead)
|
||||
}
|
||||
var ie issuanceEvent
|
||||
err := json.Unmarshal([]byte(matches[1]), &ie)
|
||||
if err != nil {
|
||||
return fmt.Errorf("line %d: failed to unmarshal JSON: %s", lNum, err)
|
||||
return fmt.Errorf("line %d: failed to unmarshal JSON: %s", linesRead, err)
|
||||
}
|
||||
|
||||
// populate the issuance time from the syslog timestamp, rather than the ResponseTime
|
||||
|
|
@ -76,9 +81,16 @@ func checkIssuances(scanner *bufio.Scanner, checkedMap map[string][]time.Time, t
|
|||
// be tightly coupled anyway.
|
||||
ie.issuanceTime, err = parseTimestamp(line)
|
||||
if err != nil {
|
||||
return fmt.Errorf("line %d: failed to parse timestamp: %s", lNum, err)
|
||||
return fmt.Errorf("line %d: failed to parse timestamp: %s", linesRead, err)
|
||||
}
|
||||
|
||||
if !earliest.IsZero() && !latest.IsZero() &&
|
||||
(ie.issuanceTime.Before(earliest) || ie.issuanceTime.After(latest)) {
|
||||
skipCount++
|
||||
continue
|
||||
}
|
||||
evaluatedCount++
|
||||
|
||||
var badNames []string
|
||||
var timeErrors []float64
|
||||
|
||||
|
|
@ -114,6 +126,9 @@ func checkIssuances(scanner *bufio.Scanner, checkedMap map[string][]time.Time, t
|
|||
if err := scanner.Err(); err != nil {
|
||||
return err
|
||||
}
|
||||
if *debug {
|
||||
fmt.Fprintf(stderr, "Issuance log lines read %d evaluated %d skipped %d\n", linesRead, evaluatedCount, skipCount)
|
||||
}
|
||||
return nil
|
||||
}
|
||||
|
||||
|
|
@ -177,12 +192,34 @@ func main() {
|
|||
raLog := flag.String("ra-log", "", "Path to a single boulder-ra log file")
|
||||
vaLogs := flag.String("va-logs", "", "List of paths to boulder-va logs, separated by commas")
|
||||
timeTolerance := flag.Duration("time-tolerance", 0, "How much slop to allow when comparing timestamps for ordering")
|
||||
earliestFlag := flag.String("earliest", "", "Day at which to start checking issuances "+
|
||||
"(inclusive). Formatted like '20060102' Optional. If specified, -latest is required.")
|
||||
latestFlag := flag.String("latest", "", "Day at which to stop checking issuances "+
|
||||
"(exclusive). Formatted like '20060102'. Optional. If specified, -earliest is required.")
|
||||
|
||||
flag.Parse()
|
||||
|
||||
if *timeTolerance < 0 {
|
||||
cmd.Fail("value of -time-tolerance must be non-negative")
|
||||
}
|
||||
|
||||
var earliest time.Time
|
||||
var latest time.Time
|
||||
if *earliestFlag != "" || *latestFlag != "" {
|
||||
if *earliestFlag == "" || *latestFlag == "" {
|
||||
cmd.Fail("-earliest and -latest must be both set or both unset")
|
||||
}
|
||||
var err error
|
||||
earliest, err = time.Parse("20060102", *earliestFlag)
|
||||
cmd.FailOnError(err, "value of -earliest could not be parsed as date")
|
||||
latest, err = time.Parse("20060102", *latestFlag)
|
||||
cmd.FailOnError(err, "value of -latest could not be parsed as date")
|
||||
|
||||
if earliest.After(latest) {
|
||||
cmd.Fail("earliest date must be before latest date")
|
||||
}
|
||||
}
|
||||
|
||||
_ = cmd.NewLogger(cmd.SyslogConfig{
|
||||
StdoutLevel: *logStdoutLevel,
|
||||
SyslogLevel: *logSyslogLevel,
|
||||
|
|
@ -196,6 +233,6 @@ func main() {
|
|||
raScanner, err := openFile(*raLog)
|
||||
cmd.FailOnError(err, fmt.Sprintf("failed to open %q", *raLog))
|
||||
|
||||
err = checkIssuances(raScanner, checkedMap, *timeTolerance, os.Stderr)
|
||||
err = checkIssuances(raScanner, checkedMap, *timeTolerance, earliest, latest, os.Stderr)
|
||||
cmd.FailOnError(err, "failed while processing RA log")
|
||||
}
|
||||
|
|
|
|||
|
|
@ -107,13 +107,17 @@ func TestCheckIssuances(t *testing.T) {
|
|||
},
|
||||
}
|
||||
|
||||
raBuf := bytes.NewBuffer([]byte(fmt.Sprintf(`random
|
||||
raString := fmt.Sprintf(`random
|
||||
%s Certificate request - successful JSON={"SerialNumber": "1", "Names":["example.com"], "Requester":0}
|
||||
random
|
||||
%s Certificate request - successful JSON={"SerialNumber": "2", "Names":["2.example.com", "3.example.com"], "Requester":0}
|
||||
%s Certificate request - successful JSON={"SerialNumber": "3", "Names":["4.example.com"], "Requester":0}
|
||||
%s Certificate request - successful JSON={"SerialNumber": "4", "Names":["5.example.com"], "Requester":0}
|
||||
%s Certificate request - successful JSON={"SerialNumber": "5", "Names":["6.example.com"], "Requester":0}
|
||||
%s Certificate request - successful JSON={"SerialNumber": "7", "Names":["7.example.com"], "Requester":0}
|
||||
%s Certificate request - successful JSON={"SerialNumber": "8", "Names":["8.example.com"], "Requester":0}
|
||||
%s Certificate request - successful JSON={"SerialNumber": "9", "Names":["9.example.com"], "Requester":0}
|
||||
%s Certificate request - successful JSON={"SerialNumber": "10", "Names":["10.example.com"], "Requester":0}
|
||||
random`,
|
||||
// example.com: CAA @ +1:00, Issue @ +2:00, CAA @ +3:00. (PASS, one valid CAA check, one invalid)
|
||||
testTime.Add(time.Hour*2).Format(time.RFC3339Nano),
|
||||
|
|
@ -126,21 +130,58 @@ random`,
|
|||
testTime.Add(10*time.Hour).Format(time.RFC3339Nano),
|
||||
// 6.example.com: Issue @ +1:00, CAA @ +1:01. (PASS, has CAA check within tolerance)
|
||||
testTime.Add(time.Hour).Format(time.RFC3339Nano),
|
||||
)))
|
||||
raScanner := bufio.NewScanner(raBuf)
|
||||
// 7.example.com: Issue @ +12:00 (PASS, no CAA check but issued after latest)
|
||||
testTime.Add(12*time.Hour).Format(time.RFC3339Nano),
|
||||
// 8.example.com: Issue @ +11:00 (FAIL, no CAA check and on latest boundary)
|
||||
testTime.Add(11*time.Hour).Format(time.RFC3339Nano),
|
||||
// 9.example.com: Issue @ -2:00 (PASS, no CAA check but issued before earliest)
|
||||
testTime.Add(-2*time.Hour).Format(time.RFC3339Nano),
|
||||
// 10.example.com: Issue @ -1:00 (FAIL, no CAA check and issued at earliest boundary)
|
||||
testTime.Add(-1*time.Hour).Format(time.RFC3339Nano),
|
||||
)
|
||||
|
||||
stderr, err := ioutil.TempFile(os.TempDir(), "stderr")
|
||||
test.AssertNotError(t, err, "failed creating temporary file")
|
||||
defer os.Remove(stderr.Name())
|
||||
for _, testCase := range []struct {
|
||||
name string
|
||||
expectedErrors string
|
||||
earliest time.Time
|
||||
latest time.Time
|
||||
}{
|
||||
{
|
||||
"with-timespan",
|
||||
"Issuance missing CAA checks: issued at=0000-12-31 19:00:00.123456 -0800 -0800, serial=2, requester=0, names=[2.example.com 3.example.com], missing checks for names=[3.example.com], timeError=[+Inf]\n" +
|
||||
"Issuance missing CAA checks: issued at=0000-12-31 17:30:00.123456 -0800 -0800, serial=3, requester=0, names=[4.example.com], missing checks for names=[4.example.com], timeError=[1800.000]\n" +
|
||||
"Issuance missing CAA checks: issued at=0001-01-01 03:00:00.123456 -0800 -0800, serial=4, requester=0, names=[5.example.com], missing checks for names=[5.example.com], timeError=[+Inf]\n" +
|
||||
"Issuance missing CAA checks: issued at=0001-01-01 04:00:00.123456 -0800 -0800, serial=8, requester=0, names=[8.example.com], missing checks for names=[8.example.com], timeError=[+Inf]\n" +
|
||||
"Issuance missing CAA checks: issued at=0000-12-31 16:00:00.123456 -0800 -0800, serial=10, requester=0, names=[10.example.com], missing checks for names=[10.example.com], timeError=[+Inf]\n",
|
||||
testTime.Add(-1 * time.Hour),
|
||||
testTime.Add(11 * time.Hour),
|
||||
},
|
||||
{
|
||||
"no-timespan",
|
||||
"Issuance missing CAA checks: issued at=0000-12-31 19:00:00.123456 -0800 -0800, serial=2, requester=0, names=[2.example.com 3.example.com], missing checks for names=[3.example.com], timeError=[+Inf]\n" +
|
||||
"Issuance missing CAA checks: issued at=0000-12-31 17:30:00.123456 -0800 -0800, serial=3, requester=0, names=[4.example.com], missing checks for names=[4.example.com], timeError=[1800.000]\n" +
|
||||
"Issuance missing CAA checks: issued at=0001-01-01 03:00:00.123456 -0800 -0800, serial=4, requester=0, names=[5.example.com], missing checks for names=[5.example.com], timeError=[+Inf]\n" +
|
||||
"Issuance missing CAA checks: issued at=0001-01-01 05:00:00.123456 -0800 -0800, serial=7, requester=0, names=[7.example.com], missing checks for names=[7.example.com], timeError=[+Inf]\n" +
|
||||
"Issuance missing CAA checks: issued at=0001-01-01 04:00:00.123456 -0800 -0800, serial=8, requester=0, names=[8.example.com], missing checks for names=[8.example.com], timeError=[+Inf]\n" +
|
||||
"Issuance missing CAA checks: issued at=0000-12-31 15:00:00.123456 -0800 -0800, serial=9, requester=0, names=[9.example.com], missing checks for names=[9.example.com], timeError=[+Inf]\n" +
|
||||
"Issuance missing CAA checks: issued at=0000-12-31 16:00:00.123456 -0800 -0800, serial=10, requester=0, names=[10.example.com], missing checks for names=[10.example.com], timeError=[+Inf]\n",
|
||||
time.Time{},
|
||||
time.Time{},
|
||||
},
|
||||
} {
|
||||
t.Run(testCase.name, func(t *testing.T) {
|
||||
raScanner := bufio.NewScanner(bytes.NewBuffer([]byte(raString)))
|
||||
stderr, err := ioutil.TempFile(os.TempDir(), "stderr")
|
||||
test.AssertNotError(t, err, "failed creating temporary file")
|
||||
defer os.Remove(stderr.Name())
|
||||
|
||||
timeTolerance := 10 * time.Minute
|
||||
err = checkIssuances(raScanner, checkedMap, timeTolerance, stderr)
|
||||
test.AssertNotError(t, err, "checkIssuances failed")
|
||||
timeTolerance := 10 * time.Minute
|
||||
err = checkIssuances(raScanner, checkedMap, timeTolerance, testCase.earliest, testCase.latest, stderr)
|
||||
test.AssertNotError(t, err, "checkIssuances failed")
|
||||
|
||||
stderrCont, err := ioutil.ReadFile(stderr.Name())
|
||||
test.AssertNotError(t, err, "failed to read temporary file")
|
||||
test.AssertEquals(t, string(stderrCont),
|
||||
"Issuance missing CAA checks: issued at=0000-12-31 19:00:00.123456 -0800 -0800, serial=2, requester=0, names=[2.example.com 3.example.com], missing checks for names=[3.example.com], timeError=[+Inf]\n"+
|
||||
"Issuance missing CAA checks: issued at=0000-12-31 17:30:00.123456 -0800 -0800, serial=3, requester=0, names=[4.example.com], missing checks for names=[4.example.com], timeError=[1800.000]\n"+
|
||||
"Issuance missing CAA checks: issued at=0001-01-01 03:00:00.123456 -0800 -0800, serial=4, requester=0, names=[5.example.com], missing checks for names=[5.example.com], timeError=[+Inf]\n")
|
||||
stderrCont, err := ioutil.ReadFile(stderr.Name())
|
||||
test.AssertNotError(t, err, "failed to read temporary file")
|
||||
test.AssertEquals(t, string(stderrCont), testCase.expectedErrors)
|
||||
})
|
||||
}
|
||||
}
|
||||
|
|
|
|||
|
|
@ -26,7 +26,7 @@ func TestCAALogChecker(t *testing.T) {
|
|||
test.AssertEquals(t, len(result.Order.Authorizations), 1)
|
||||
|
||||
// Should be no specific output, since everything is good
|
||||
cmd := exec.Command("bin/caa-log-checker", "-ra-log", "/var/log/boulder-ra.log", "-va-logs", "/var/log/boulder-va.log")
|
||||
cmd := exec.Command("bin/caa-log-checker", "-ra-log", "/var/log/boulder-ra.log", "-va-logs", "/var/log/boulder-va.log", "-earliest", "19010101", "-latest", "30000101")
|
||||
var stdErr bytes.Buffer
|
||||
cmd.Stderr = &stdErr
|
||||
out, err := cmd.Output()
|
||||
|
|
|
|||
Loading…
Reference in New Issue