| // Copyright 2020 The Fuchsia Authors. All rights reserved. |
| // Use of this source code is governed by a BSD-style license that can be |
| // found in the LICENSE file. |
| |
| package tefmocheck |
| |
| import ( |
| "bytes" |
| "fmt" |
| "path" |
| "path/filepath" |
| "strings" |
| |
| "go.fuchsia.dev/fuchsia/tools/bootserver/bootserverconstants" |
| botanistconstants "go.fuchsia.dev/fuchsia/tools/botanist/constants" |
| ffxutilconstants "go.fuchsia.dev/fuchsia/tools/lib/ffxutil/constants" |
| serialconstants "go.fuchsia.dev/fuchsia/tools/lib/serial/constants" |
| syslogconstants "go.fuchsia.dev/fuchsia/tools/lib/syslog/constants" |
| netutilconstants "go.fuchsia.dev/fuchsia/tools/net/netutil/constants" |
| sshutilconstants "go.fuchsia.dev/fuchsia/tools/net/sshutil/constants" |
| testrunnerconstants "go.fuchsia.dev/fuchsia/tools/testing/testrunner/constants" |
| ) |
| |
| // stringInLogCheck checks if String is found in the log named LogName. |
| type stringInLogCheck struct { |
| // String that will be searched for. |
| String string |
| // OnlyOnStates will cause Check() to return false if the swarming task |
| // state doesn't match with one of these states. |
| OnlyOnStates []string |
| // ExceptString will cause Check() to return false if present. |
| ExceptString string |
| // ExceptBlocks will cause Check() to return false if the string is only |
| // within these blocks. The start string and end string should be unique |
| // strings that only appear around the except block. A stray start string |
| // will cause everything after it to be included in the except block even |
| // if the end string is missing. |
| ExceptBlocks []*logBlock |
| // SkipPassedTask will cause Check() to return false if the |
| // Swarming task succeeded. |
| SkipPassedTask bool |
| // Type of log that will be checked. |
| Type logType |
| // Whether to check the per-test Swarming output for this log and emit a |
| // check that's specific to the test during which the log appeared. |
| AttributeToTest bool |
| |
| swarmingResult *SwarmingRpcsTaskResult |
| testName string |
| outputFile string |
| } |
| |
| func (c *stringInLogCheck) Check(to *TestingOutputs) bool { |
| c.swarmingResult = to.SwarmingSummary.Results |
| if c.SkipPassedTask && !c.swarmingResult.Failure && c.swarmingResult.State == "COMPLETED" { |
| return false |
| } |
| matchedState := false |
| for _, state := range c.OnlyOnStates { |
| if c.swarmingResult.State == state { |
| matchedState = true |
| break |
| } |
| } |
| if len(c.OnlyOnStates) != 0 && !matchedState { |
| return false |
| } |
| |
| if c.Type == swarmingOutputType && c.AttributeToTest { |
| for _, testLog := range to.SwarmingOutputPerTest { |
| if c.checkBytes(to.SwarmingOutput, testLog.Index, testLog.Index+len(testLog.Bytes)) { |
| c.testName = testLog.TestName |
| c.outputFile = testLog.FilePath |
| return true |
| } |
| } |
| } |
| |
| var toCheck [][]byte |
| switch c.Type { |
| case serialLogType: |
| toCheck = to.SerialLogs |
| case swarmingOutputType: |
| toCheck = [][]byte{to.SwarmingOutput} |
| case syslogType: |
| toCheck = to.Syslogs |
| } |
| |
| for _, file := range toCheck { |
| if c.checkBytes(file, 0, len(file)) { |
| return true |
| } |
| } |
| return false |
| } |
| |
| func (c *stringInLogCheck) checkBytes(toCheck []byte, start int, end int) bool { |
| toCheckBlock := toCheck[start:end] |
| if c.ExceptString != "" && bytes.Contains(toCheckBlock, []byte(c.ExceptString)) { |
| return false |
| } |
| stringBytes := []byte(c.String) |
| if len(c.ExceptBlocks) == 0 { |
| return bytes.Contains(toCheckBlock, stringBytes) |
| } |
| index := bytes.Index(toCheckBlock, stringBytes) + start |
| for index >= start && index < end { |
| foundString := true |
| beforeBlock := toCheck[:index] |
| nextStartIndex := index + len(stringBytes) |
| afterBlock := toCheck[nextStartIndex:] |
| for _, block := range c.ExceptBlocks { |
| closestStartIndex := bytes.LastIndex(beforeBlock, []byte(block.startString)) |
| if closestStartIndex < 0 { |
| // There is no start string before this occurrence, so it must not be |
| // included in this exceptBlock. Check the next exceptBlock. |
| continue |
| } |
| closestEndIndex := bytes.LastIndex(beforeBlock, []byte(block.endString)) |
| if closestEndIndex < closestStartIndex { |
| // There is no end string between the start string and the string to |
| // check, so check if end string appears after. If so, then this |
| // occurrence is included in this exceptBlock, so we can break and |
| // check the next occurrence of the string. |
| if bytes.Contains(afterBlock, []byte(block.endString)) { |
| foundString = false |
| break |
| } else { |
| // If the end string doesn't appear after the string to check, |
| // it may have been truncated out of the log. In that case, we |
| // assume every occurrence of the string to check between the |
| // start string and the end of the block are included in the |
| // exceptBlock. |
| return false |
| } |
| } |
| } |
| if foundString { |
| return true |
| } |
| index = bytes.Index(afterBlock, stringBytes) |
| if index >= 0 { |
| index += nextStartIndex |
| } |
| } |
| return false |
| } |
| |
| func (c *stringInLogCheck) Name() string { |
| // TODO(fxbug.dev/71529): With multi-device logs, the file names may be different than |
| // the log type. Consider using the actual filename of the log. |
| return path.Join("string_in_log", string(c.Type), strings.ReplaceAll(c.String, " ", "_"), c.testName) |
| } |
| |
| func (c *stringInLogCheck) DebugText() string { |
| debugStr := fmt.Sprintf("Found the string \"%s\" in ", c.String) |
| if c.outputFile != "" && c.testName != "" { |
| debugStr += fmt.Sprintf("%s of test %s.", filepath.Base(c.outputFile), c.testName) |
| } else { |
| debugStr += fmt.Sprintf("%s for task %s.", c.Type, c.swarmingResult.TaskId) |
| } |
| debugStr += "\nThat file should be accessible from the build result page or Sponge.\n" |
| if c.ExceptString != "" { |
| debugStr += fmt.Sprintf("\nDid not find the exception string \"%s\"", c.ExceptString) |
| } |
| if len(c.ExceptBlocks) > 0 { |
| for _, block := range c.ExceptBlocks { |
| debugStr += fmt.Sprintf("\nDid not occur inside a block delimited by:\nSTART: %s\nEND: %s", block.startString, block.endString) |
| } |
| } |
| return debugStr |
| } |
| |
| func (c *stringInLogCheck) OutputFiles() []string { |
| if c.outputFile == "" { |
| return []string{} |
| } |
| return []string{c.outputFile} |
| } |
| |
| // StringInLogsChecks returns checks to detect bad strings in certain logs. |
| func StringInLogsChecks() []FailureModeCheck { |
| ret := []FailureModeCheck{ |
| // For fxbug.dev/85875 |
| // This is printed by Swarming after a Swarming task's command completes, and |
| // suggests that a test leaked a subprocess that modified one of the task's |
| // output files after the task's command completed but before Swarming finished |
| // uploading outputs. |
| // |
| // This is a serious issue and always causes the Swarming task to fail, |
| // so we prioritize it over all other checks. |
| &stringInLogCheck{String: "error: blob size changed while uploading", Type: swarmingOutputType}, |
| // Failure modes for CAS uploads from Swarming tasks during task cleanup |
| // (outside the scope of the command run during the task). These logs |
| // are unfortunately copy-pasted from the luci-go repository. These |
| // failures are generally a result of a degradation in the upstream |
| // RBE-CAS service. |
| &stringInLogCheck{ |
| String: "cas: failed to call UploadIfMissing", |
| Type: swarmingOutputType, |
| OnlyOnStates: []string{"BOT_DIED"}, |
| }, |
| &stringInLogCheck{ |
| String: "cas: failed to create cas client", |
| Type: swarmingOutputType, |
| OnlyOnStates: []string{"BOT_DIED"}, |
| }, |
| } |
| // Many of the infra tool checks match failure modes that have a root cause |
| // somewhere within Fuchsia itself, so we want to make sure to check for |
| // failures within the OS first to make sure we get as close to the root |
| // cause as possible. |
| ret = append(ret, fuchsiaLogChecks()...) |
| ret = append(ret, infraToolLogChecks()...) |
| return ret |
| } |
| |
| // fuchsiaLogChecks returns checks for logs that come from the target Fuchsia |
| // device rather than from infrastructure host tools. |
| func fuchsiaLogChecks() []FailureModeCheck { |
| ret := []FailureModeCheck{ |
| // For fxbug.dev/57548. |
| // Hardware watchdog tripped, should not happen. |
| // This string is specified in u-boot. |
| // Astro uses an equal sign, Sherlock uses a colon. Consider allowing |
| // regexes? |
| // It is fine to have the two different checks because bug filing logic |
| // already breaks down by device type. |
| &stringInLogCheck{String: "reboot_mode=watchdog_reboot", Type: serialLogType}, |
| &stringInLogCheck{String: "reboot_mode:watchdog_reboot", Type: serialLogType}, |
| // For fxbug.dev/55637 |
| &stringInLogCheck{String: " in fx_logger::GetSeverity() ", Type: swarmingOutputType}, |
| // For fxbug.dev/71784. Do not check for this in swarming output as this does not indicate |
| // an error if logged by unit tests. |
| &stringInLogCheck{String: "intel-i915: No displays detected.", Type: serialLogType}, |
| &stringInLogCheck{String: "intel-i915: No displays detected.", Type: syslogType}, |
| } |
| |
| oopsExceptBlocks := []*logBlock{ |
| {startString: " lock_dep_dynamic_analysis_tests ", endString: " lock_dep_static_analysis_tests "}, |
| {startString: "RUN TestKillCriticalProcess", endString: ": TestKillCriticalProcess"}, |
| {startString: "RUN TestKernelLockupDetectorCriticalSection", endString: ": TestKernelLockupDetectorCriticalSection"}, |
| {startString: "RUN TestKernelLockupDetectorHeartbeat", endString: ": TestKernelLockupDetectorHeartbeat"}, |
| {startString: "RUN TestPmmCheckerOopsAndPanic", endString: ": TestPmmCheckerOopsAndPanic"}, |
| {startString: "RUN TestKernelLockupDetectorFatalCriticalSection", endString: ": TestKernelLockupDetectorFatalCriticalSection"}, |
| {startString: "RUN TestKernelLockupDetectorFatalHeartbeat", endString: ": TestKernelLockupDetectorFatalHeartbeat"}, |
| } |
| // These are rather generic. New checks should probably go above here so that they run before these. |
| allLogTypes := []logType{serialLogType, swarmingOutputType, syslogType} |
| for _, lt := range allLogTypes { |
| // For fxbug.dev/43355. |
| ret = append(ret, []FailureModeCheck{ |
| &stringInLogCheck{String: "Timed out loading dynamic linker from fuchsia.ldsvc.Loader", Type: lt}, |
| &stringInLogCheck{String: "ERROR: AddressSanitizer", Type: lt, AttributeToTest: true}, |
| &stringInLogCheck{String: "ERROR: LeakSanitizer", Type: lt, AttributeToTest: true, ExceptBlocks: []*logBlock{ |
| // startString and endString should match string in //zircon/system/ulib/c/test/sanitizer/lsan-test.cc. |
| {startString: "[===LSAN EXCEPT BLOCK START===]", endString: "[===LSAN EXCEPT BLOCK END===]"}, |
| // Kernel out-of-memory test "OOMHard" may report false positive leaks. |
| {startString: "RUN TestOOMHard", endString: "PASS: TestOOMHard"}, |
| }}, |
| &stringInLogCheck{String: "WARNING: ThreadSanitizer", Type: lt, AttributeToTest: true}, |
| &stringInLogCheck{String: "SUMMARY: UndefinedBehaviorSanitizer", Type: lt, AttributeToTest: true}, |
| // Match specific OOPS types before finally matching the generic type. |
| &stringInLogCheck{String: "lockup_detector: no heartbeat from", Type: lt, AttributeToTest: true, ExceptBlocks: oopsExceptBlocks}, |
| &stringInLogCheck{String: "ZIRCON KERNEL OOPS", Type: lt, AttributeToTest: true, ExceptBlocks: oopsExceptBlocks}, |
| &stringInLogCheck{String: "ZIRCON KERNEL PANIC", AttributeToTest: true, Type: lt, ExceptBlocks: []*logBlock{ |
| // These tests intentionally trigger kernel panics. |
| {startString: "RUN TestBasicCrash", endString: "PASS: TestBasicCrash"}, |
| {startString: "RUN TestReadUserMemoryViolation", endString: "PASS: TestReadUserMemoryViolation"}, |
| {startString: "RUN TestExecuteUserMemoryViolation", endString: "PASS: TestExecuteUserMemoryViolation"}, |
| {startString: "RUN TestPmmCheckerOopsAndPanic", endString: "PASS: TestPmmCheckerOopsAndPanic"}, |
| {startString: "RUN TestCrashAssert", endString: "PASS: TestCrashAssert"}, |
| {startString: "RUN TestKernelLockupDetectorFatalCriticalSection", endString: ": TestKernelLockupDetectorFatalCriticalSection"}, |
| {startString: "RUN TestKernelLockupDetectorFatalHeartbeat", endString: ": TestKernelLockupDetectorFatalHeartbeat"}, |
| {startString: "RUN TestMissingCmdlineEntropyPanics", endString: "PASS: TestMissingCmdlineEntropyPanics"}, |
| {startString: "RUN TestIncompleteCmdlineEntropyPanics", endString: "PASS: TestIncompleteCmdlineEntropyPanics"}, |
| {startString: "RUN TestDisabledJitterEntropyAndRequiredDoesntBoot", endString: "PASS: TestDisabledJitterEntropyAndRequiredDoesntBoot"}, |
| {startString: "RUN TestDisabledJitterEntropyAndRequiredForReseedDoesntReachUserspace", endString: "PASS: TestDisabledJitterEntropyAndRequiredForReseedDoesntReachUserspace"}, |
| }}, |
| &stringInLogCheck{String: "double fault, halting", Type: lt}, |
| // This string can show up in some zbi tests. |
| &stringInLogCheck{String: "entering panic shell loop", Type: lt, ExceptString: "ZBI-test-successful!"}, |
| }...) |
| } |
| |
| ret = append(ret, []FailureModeCheck{ |
| // These may be in the output of tests, but the syslogType doesn't contain any test output. |
| &stringInLogCheck{String: "ASSERT FAILED", Type: syslogType}, |
| &stringInLogCheck{String: "DEVICE SUSPEND TIMED OUT", Type: syslogType}, |
| // For fxbug.dev/61419. |
| // Error is being logged at https://fuchsia.googlesource.com/fuchsia/+/675c6b9cc2452cd7108f075d91e048218b92ae69/garnet/bin/run_test_component/main.cc#431 |
| &stringInLogCheck{ |
| String: ".cmx canceled due to timeout.", |
| Type: swarmingOutputType, |
| ExceptBlocks: []*logBlock{ |
| { |
| startString: "[ RUN ] RunFixture.TestTimeout", |
| endString: "RunFixture.TestTimeout (", |
| }, |
| }, |
| OnlyOnStates: []string{"TIMED_OUT"}, |
| }, |
| &stringInLogCheck{ |
| String: "failed to resolve fuchsia-pkg://fuchsia.com/run_test_component#bin/run-test-component", |
| Type: swarmingOutputType, |
| }, |
| &stringInLogCheck{ |
| String: "Got no package for fuchsia-pkg://", |
| Type: swarmingOutputType, |
| }, |
| }...) |
| return ret |
| } |
| |
| // infraToolLogChecks returns all the checks for logs that are emitted by |
| // infrastructure host tools. |
| func infraToolLogChecks() []FailureModeCheck { |
| return []FailureModeCheck{ |
| // For fxbug.dev/47649. |
| &stringInLogCheck{String: "kvm run failed Bad address", Type: swarmingOutputType}, |
| // For fxbug.dev/44779. |
| &stringInLogCheck{String: netutilconstants.CannotFindNodeErrMsg, Type: swarmingOutputType}, |
| // For fxbug.dev/51015. |
| &stringInLogCheck{ |
| String: bootserverconstants.FailedToSendErrMsg(bootserverconstants.CmdlineNetsvcName), |
| Type: swarmingOutputType, |
| SkipPassedTask: true, |
| }, |
| // For fxbug.dev/43188. |
| &stringInLogCheck{String: "/dev/net/tun (qemu): Device or resource busy", Type: swarmingOutputType}, |
| // testrunner logs this when the serial socket goes away unexpectedly. |
| &stringInLogCheck{String: ".sock: write: broken pipe", Type: swarmingOutputType}, |
| // For fxbug.dev/85596. |
| &stringInLogCheck{String: "connect: no route to host", Type: swarmingOutputType}, |
| // For fxbug.dev/57463. |
| &stringInLogCheck{ |
| String: fmt.Sprintf("%s: signal: segmentation fault", botanistconstants.QEMUInvocationErrorMsg), |
| Type: swarmingOutputType, |
| }, |
| // For fxbug.dev/61452. |
| &stringInLogCheck{ |
| String: fmt.Sprintf("botanist ERROR: %s", botanistconstants.FailedToResolveIPErrorMsg), |
| Type: swarmingOutputType, |
| }, |
| // For fxbug.dev/65073. |
| &stringInLogCheck{ |
| String: fmt.Sprintf("botanist ERROR: %s", botanistconstants.PackageRepoSetupErrorMsg), |
| Type: swarmingOutputType, |
| }, |
| // For fxbug.dev/65073. |
| &stringInLogCheck{ |
| String: fmt.Sprintf("botanist ERROR: %s", botanistconstants.SerialReadErrorMsg), |
| Type: swarmingOutputType, |
| }, |
| // For fxbug.dev/68743. |
| &stringInLogCheck{ |
| String: botanistconstants.FailedToCopyImageMsg, |
| Type: swarmingOutputType, |
| }, |
| // For fxbug.dev/82454. |
| &stringInLogCheck{ |
| String: botanistconstants.FailedToExtendFVMMsg, |
| Type: swarmingOutputType, |
| }, |
| // Error is being logged at https://fuchsia.googlesource.com/fuchsia/+/559948a1a4cbd995d765e26c32923ed862589a61/src/storage/lib/paver/paver.cc#175 |
| &stringInLogCheck{ |
| String: "Failed to stream partitions to FVM", |
| Type: swarmingOutputType, |
| }, |
| // Emitted by the GCS Go library during image download. |
| &stringInLogCheck{ |
| String: bootserverconstants.BadCRCErrorMsg, |
| Type: swarmingOutputType, |
| // This error is generally transient, so ignore it as long as the |
| // download can be retried and eventually succeeds. |
| SkipPassedTask: true, |
| }, |
| // For fxbug.dev/89222. |
| &stringInLogCheck{ |
| String: serialconstants.FailedToOpenSerialSocketMsg, |
| Type: swarmingOutputType, |
| }, |
| // For fxbug.dev/89437 |
| &stringInLogCheck{ |
| String: serialconstants.FailedToFindCursorMsg, |
| Type: swarmingOutputType, |
| }, |
| // For fxbug.dev/103197. Usually indicates an issue with the bot. If the bots |
| // with the failures have been consistently failing with the same error, file |
| // a go/fxif-bug for the suspected bad bots. |
| &stringInLogCheck{ |
| String: "server canceled transfer: could not open file for writing", |
| Type: swarmingOutputType, |
| // This error may appear as part of a test, so ignore unless it happens |
| // during device setup which will cause a task failure. |
| SkipPassedTask: true, |
| }, |
| // For fxbug.dev/53101. |
| &stringInLogCheck{ |
| String: fmt.Sprintf("botanist ERROR: %s", botanistconstants.FailedToStartTargetMsg), |
| Type: swarmingOutputType, |
| }, |
| // For fxbug.dev/51441. |
| &stringInLogCheck{ |
| String: fmt.Sprintf("botanist ERROR: %s", botanistconstants.ReadConfigFileErrorMsg), |
| Type: swarmingOutputType, |
| }, |
| // For fxbug.dev/59237. |
| &stringInLogCheck{ |
| String: fmt.Sprintf("botanist ERROR: %s", sshutilconstants.TimedOutConnectingMsg), |
| Type: swarmingOutputType, |
| }, |
| // For fxbug.dev/61420. |
| &stringInLogCheck{ |
| String: fmt.Sprintf("syslog: %s", syslogconstants.CtxReconnectError), |
| Type: swarmingOutputType, |
| OnlyOnStates: []string{"TIMED_OUT"}, |
| }, |
| // For fxbug.dev/52719. |
| // Kernel panics and other low-level errors often cause crashes that |
| // manifest as SSH failures, so this check must come after all |
| // Zircon-related errors to ensure tefmocheck attributes these crashes to |
| // the actual root cause. |
| &stringInLogCheck{ |
| String: fmt.Sprintf("testrunner ERROR: %s", testrunnerconstants.FailedToReconnectMsg), |
| Type: swarmingOutputType, |
| }, |
| // For fxbug.dev/77689. |
| &stringInLogCheck{ |
| String: testrunnerconstants.FailedToStartSerialTestMsg, |
| Type: swarmingOutputType, |
| }, |
| // For fxbug.dev/92141. |
| &stringInLogCheck{ |
| String: ffxutilconstants.TimeoutReachingTargetMsg, |
| Type: swarmingOutputType, |
| }, |
| // General ffx error check. |
| &stringInLogCheck{ |
| String: ffxutilconstants.CommandFailedMsg, |
| Type: swarmingOutputType, |
| }, |
| // This error happens when ffx test returns early and skips running some tests. |
| &stringInLogCheck{ |
| String: fmt.Sprintf("testrunner FATAL: %s", testrunnerconstants.SkippedRunningTestsMsg), |
| Type: swarmingOutputType, |
| }, |
| // For fxbug.dev/56651. |
| // This error usually happens due to an SSH failure, so that error should take precedence. |
| &stringInLogCheck{ |
| String: fmt.Sprintf("testrunner ERROR: %s", testrunnerconstants.FailedToRunSnapshotMsg), |
| Type: swarmingOutputType, |
| }, |
| // This error happens when `botanist run` exceeds its timeout, e.g. |
| // because many tests are taking too long. |
| &stringInLogCheck{ |
| String: fmt.Sprintf("botanist ERROR: %s", botanistconstants.CommandExceededTimeoutMsg), |
| Type: swarmingOutputType, |
| }, |
| // This error is emitted by `fastboot` when it fails to write an image |
| // to the disk. It is generally caused by ECC errors. |
| &stringInLogCheck{ |
| String: "FAILED (remote: 'error writing the image')", |
| Type: swarmingOutputType, |
| }, |
| } |
| } |
