| // Copyright 2020 The Chromium OS 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 firmware |
| |
| import ( |
| "context" |
| "fmt" |
| "regexp" |
| "strconv" |
| "time" |
| |
| gossh "golang.org/x/crypto/ssh" |
| |
| fwCommon "chromiumos/tast/common/firmware" |
| "chromiumos/tast/common/servo" |
| "chromiumos/tast/errors" |
| "chromiumos/tast/remote/firmware" |
| "chromiumos/tast/remote/firmware/fixture" |
| "chromiumos/tast/remote/firmware/reporters" |
| "chromiumos/tast/ssh" |
| "chromiumos/tast/testing" |
| "chromiumos/tast/testing/hwdep" |
| ) |
| |
| // eventLogParams contains all the data needed to run a single test iteration. |
| type eventLogParams struct { |
| resetType firmware.ResetType |
| bootToMode fwCommon.BootMode |
| suspendResume bool |
| suspendToIdle string |
| hardwareWatchdog bool |
| // All of the regexes in one of the sets must be present. Ex. |
| // [][]string{[]string{`Case 1A`, `Case 1B`}, []string{`Case 2A`, `Case 2[BC]`}} |
| // Any of these events would pass: |
| // Case 1A, Case 1B |
| // Case 2A, Case 2B |
| // Case 2A, Case 2C |
| requiredEventSets [][]string |
| prohibitedEvents string |
| allowedEvents string |
| } |
| |
| func init() { |
| testing.AddTest(&testing.Test{ |
| Func: Eventlog, |
| Desc: "Ensure that eventlog is written on boot and suspend/resume", |
| Contacts: []string{ |
| "gredelston@google.com", // Test author. |
| "cros-fw-engprod@google.com", |
| }, |
| Attr: []string{"group:firmware"}, |
| HardwareDeps: hwdep.D( |
| // Eventlog is broken/wontfix on veyron devices. |
| // See http://b/35585376#comment14 for more info. |
| hwdep.SkipOnPlatform("veyron_fievel"), |
| hwdep.SkipOnPlatform("veyron_tiger"), |
| ), |
| SoftwareDeps: []string{"crossystem", "flashrom"}, |
| Vars: []string{"firmware.skipFlashUSB"}, |
| Params: []testing.Param{ |
| // Test eventlog upon normal->normal reboot. |
| { |
| Name: "normal", |
| ExtraAttr: []string{"firmware_unstable"}, |
| ExtraHardwareDeps: hwdep.D(hwdep.SkipOnModel("leona")), |
| Fixture: fixture.NormalMode, |
| Val: eventLogParams{ |
| resetType: firmware.WarmReset, |
| requiredEventSets: [][]string{{`System boot`}}, |
| prohibitedEvents: `Developer Mode|Recovery Mode|Sleep| Wake`, |
| }, |
| }, |
| { |
| // Allow some normally disallowed events on leona. b/184778308 |
| Name: "leona_normal", |
| ExtraAttr: []string{"firmware_ec"}, |
| ExtraHardwareDeps: hwdep.D(hwdep.Model("leona")), |
| Fixture: fixture.NormalMode, |
| Val: eventLogParams{ |
| resetType: firmware.WarmReset, |
| requiredEventSets: [][]string{{`System boot`}}, |
| prohibitedEvents: `Developer Mode|Recovery Mode|Sleep| Wake`, |
| allowedEvents: `^ACPI Wake \| Deep S5$`, |
| }, |
| }, |
| // Test eventlog upon dev->dev reboot. |
| { |
| Name: "dev", |
| ExtraAttr: []string{"firmware_ec"}, |
| ExtraHardwareDeps: hwdep.D(hwdep.SkipOnModel("leona")), |
| Fixture: fixture.DevModeGBB, |
| Val: eventLogParams{ |
| resetType: firmware.WarmReset, |
| requiredEventSets: [][]string{{`System boot`, `Chrome OS Developer Mode`}}, |
| prohibitedEvents: `Recovery Mode|Sleep| Wake`, |
| }, |
| }, |
| // Allow some normally disallowed events on leona. b/184778308 |
| { |
| Name: "leona_dev", |
| ExtraAttr: []string{"firmware_ec"}, |
| ExtraHardwareDeps: hwdep.D(hwdep.Model("leona")), |
| Fixture: fixture.DevModeGBB, |
| Val: eventLogParams{ |
| resetType: firmware.WarmReset, |
| requiredEventSets: [][]string{{`System boot`, `Chrome OS Developer Mode`}}, |
| prohibitedEvents: `Recovery Mode|Sleep| Wake`, |
| allowedEvents: `^ACPI Wake \| Deep S5$`, |
| }, |
| }, |
| // Test eventlog upon normal->rec reboot. |
| { |
| Name: "normal_rec", |
| ExtraAttr: []string{"firmware_unstable", "firmware_usb"}, |
| Fixture: fixture.NormalMode, |
| Val: eventLogParams{ |
| bootToMode: fwCommon.BootModeRecovery, |
| requiredEventSets: [][]string{{`System boot`, `Chrome OS Recovery Mode \| Recovery Button`}}, |
| prohibitedEvents: `Developer Mode|Sleep|FW Wake|ACPI Wake \| S3`, |
| }, |
| Timeout: 60 * time.Minute, |
| }, |
| // Test eventlog upon rec->normal reboot. |
| { |
| Name: "rec_normal", |
| ExtraAttr: []string{"firmware_unstable", "firmware_usb"}, |
| Fixture: fixture.RecModeNoServices, |
| Val: eventLogParams{ |
| bootToMode: fwCommon.BootModeNormal, |
| requiredEventSets: [][]string{{`System boot`}}, |
| prohibitedEvents: `Developer Mode|Recovery Mode|Sleep`, |
| }, |
| Timeout: 6 * time.Minute, |
| }, |
| // Test eventlog upon suspend/resume w/ default value of suspend_to_idle. |
| // treeya: ACPI Enter | S3, EC Event | Power Button, ACPI Wake | S3, Wake Source | Power Button | 0 |
| // kindred: S0ix Enter, S0ix Exit, Wake Source | Power Button | 0, EC Event | Power Button |
| // leona: S0ix Enter, S0ix Exit, Wake Source | Power Button | 0, EC Event | Power Button |
| // eldrid: S0ix Enter, S0ix Exit, Wake Source | Power Button | 0, EC Event | Power Button |
| // hayato: Sleep, Wake |
| { |
| Name: "suspend_resume", |
| ExtraAttr: []string{"firmware_unstable"}, |
| Fixture: fixture.NormalMode, |
| Val: eventLogParams{ |
| suspendResume: true, |
| requiredEventSets: [][]string{ |
| {`Sleep`, `^Wake`}, |
| {`ACPI Enter \| S3`, `ACPI Wake \| S3`}, |
| {`S0ix Enter`, `S0ix Exit`}, |
| }, |
| prohibitedEvents: `System |Developer Mode|Recovery Mode`, |
| }, |
| }, |
| // Test eventlog upon suspend/resume w/ suspend_to_idle. |
| // On supported machines, this should go to S0ix or stay in S0. |
| // x86 duts: S0ix Enter, S0ix Exit, Wake Source | Power Button | 0, EC Event | Power Button |
| // hayato: FAIL Sleep, System boot |
| // treeya: FAIL Nothing logged |
| { |
| Name: "suspend_resume_idle", |
| ExtraAttr: []string{"firmware_unstable"}, |
| Fixture: fixture.NormalMode, |
| Val: eventLogParams{ |
| suspendResume: true, |
| suspendToIdle: "1", |
| requiredEventSets: [][]string{ |
| {`Sleep`, `^Wake`}, |
| {`S0ix Enter`, `S0ix Exit`}, |
| }, |
| prohibitedEvents: `System |Developer Mode|Recovery Mode`, |
| }, |
| }, |
| // Test eventlog upon suspend/resume w/o suspend_to_idle. |
| // This should power down all the way to S3. |
| // eldrid: FAIL ACPI Enter | S3, EC Event | Power Button, ACPI Wake | S3, Wake Source | Power Button | 0 -> Gets stuck and doesn't boot. |
| // hayato: Sleep, Wake |
| // x86 duts: ACPI Enter | S3, EC Event | Power Button, ACPI Wake | S3, Wake Source | Power Button | 0 |
| { |
| Name: "suspend_resume_noidle", |
| ExtraAttr: []string{"firmware_unstable"}, |
| Fixture: fixture.NormalMode, |
| Val: eventLogParams{ |
| suspendResume: true, |
| suspendToIdle: "0", |
| requiredEventSets: [][]string{ |
| {`Sleep`, `^Wake`}, |
| {`ACPI Enter \| S3`, `ACPI Wake \| S3`}, |
| }, |
| prohibitedEvents: `System |Developer Mode|Recovery Mode`, |
| }, |
| }, |
| // Test eventlog with hardware watchdog. |
| { |
| Name: "watchdog", |
| ExtraAttr: []string{"firmware_ec"}, |
| Fixture: fixture.NormalMode, |
| ExtraSoftwareDeps: []string{"watchdog"}, |
| Val: eventLogParams{ |
| hardwareWatchdog: true, |
| requiredEventSets: [][]string{ |
| {`System boot|Hardware watchdog reset`}, |
| }, |
| }, |
| }, |
| }, |
| }) |
| } |
| |
| // eventMessagesContainReMatch returns true if any event's message matches the regexp. |
| func eventMessagesContainReMatch(ctx context.Context, events []reporters.Event, re *regexp.Regexp) bool { |
| for _, event := range events { |
| if re.MatchString(event.Message) { |
| return true |
| } |
| } |
| return false |
| } |
| |
| func Eventlog(ctx context.Context, s *testing.State) { |
| // Create mode-switcher. |
| v := s.FixtValue().(*fixture.Value) |
| h := v.Helper |
| if err := h.RequireServo(ctx); err != nil { |
| s.Fatal("Failed to connect to servod") |
| } |
| ms, err := firmware.NewModeSwitcher(ctx, h) |
| if err != nil { |
| s.Fatal("Creating mode switcher: ", err) |
| } |
| r := h.Reporter |
| param := s.Param().(eventLogParams) |
| |
| var cutoffEvent reporters.Event |
| oldEvents, err := r.EventlogList(ctx) |
| if err != nil { |
| s.Fatal("Finding last event: ", err) |
| } |
| if len(oldEvents) > 0 { |
| cutoffEvent = oldEvents[len(oldEvents)-1] |
| s.Log("Found previous event: ", cutoffEvent) |
| } |
| if param.resetType != "" { |
| if err := ms.ModeAwareReboot(ctx, param.resetType); err != nil { |
| s.Fatal("Error resetting DUT: ", err) |
| } |
| } else if param.bootToMode != "" { |
| // If booting into recovery, check the USB Key. |
| if param.bootToMode == fwCommon.BootModeRecovery { |
| skipFlashUSB := false |
| if skipFlashUSBStr, ok := s.Var("firmware.skipFlashUSB"); ok { |
| skipFlashUSB, err = strconv.ParseBool(skipFlashUSBStr) |
| if err != nil { |
| s.Fatalf("Invalid value for var firmware.skipFlashUSB: got %q, want true/false", skipFlashUSBStr) |
| } |
| } |
| cs := s.CloudStorage() |
| if skipFlashUSB { |
| cs = nil |
| } |
| if err := h.SetupUSBKey(ctx, cs); err != nil { |
| s.Fatal("USBKey not working: ", err) |
| } |
| } |
| if err := ms.RebootToMode(ctx, param.bootToMode); err != nil { |
| s.Fatalf("Error during transition to %s: %+v", param.bootToMode, err) |
| } |
| } else if param.suspendResume { |
| if err := h.Servo.WatchdogRemove(ctx, servo.WatchdogCCD); err != nil { |
| s.Error("Failed to remove watchdog for ccd: ", err) |
| } |
| if param.suspendToIdle != "" { |
| if err := h.DUT.Conn().CommandContext(ctx, "sh", "-c", fmt.Sprintf( |
| "mkdir -p /tmp/power_manager && "+ |
| "echo %q > /tmp/power_manager/suspend_to_idle && "+ |
| "mount --bind /tmp/power_manager /var/lib/power_manager && "+ |
| "restart powerd", param.suspendToIdle), |
| ).Run(ssh.DumpLogOnError); err != nil { |
| s.Fatal("Failed to set suspend to idle: ", err) |
| } |
| defer func(ctx context.Context) { |
| if err := h.DUT.Conn().CommandContext(ctx, "sh", "-c", |
| "umount /var/lib/power_manager && restart powerd", |
| ).Run(ssh.DumpLogOnError); err != nil { |
| s.Log("Failed to restore powerd settings: ", err) |
| } |
| }(ctx) |
| // Suspend will fail right after restarting powerd. |
| testing.Sleep(ctx, 2*time.Second) |
| } |
| h.CloseRPCConnection(ctx) |
| |
| s.Log("Suspending DUT") |
| shortCtx, cancel := context.WithTimeout(ctx, 3*time.Second) |
| defer cancel() |
| if err := h.DUT.Conn().CommandContext(shortCtx, "powerd_dbus_suspend").Run(ssh.DumpLogOnError); err != nil && |
| !errors.Is(err, context.DeadlineExceeded) && !errors.Is(err, &gossh.ExitMissingError{}) { |
| s.Fatal("Failed to suspend: ", err) |
| } |
| |
| // Let the DUT stay in suspend a little while. 10s seems to be enough to allow wake up. Shorter times might work also. |
| if err := testing.Sleep(ctx, 10*time.Second); err != nil { |
| s.Fatal("Failed to sleep: ", err) |
| } |
| |
| powerState, err := h.Servo.GetECSystemPowerState(ctx) |
| if err != nil { |
| s.Error("Failed to get power state: ", err) |
| } |
| s.Log("Power state: ", powerState) |
| |
| s.Log("Pressing ENTER key to wake DUT") |
| if err := h.Servo.KeypressWithDuration(ctx, servo.Enter, servo.DurTab); err != nil { |
| s.Fatal("Failed to press enter key") |
| } |
| |
| s.Log("Reconnecting to DUT") |
| shortCtx, cancel = context.WithTimeout(ctx, 60*time.Second) |
| defer cancel() |
| if err := h.WaitConnect(shortCtx); err != nil { |
| s.Fatal("Failed to reconnect to DUT: ", err) |
| } |
| s.Log("Reconnected to DUT") |
| } else if param.hardwareWatchdog { |
| if err := h.Servo.WatchdogRemove(ctx, servo.WatchdogCCD); err != nil { |
| s.Error("Failed to remove watchdog for ccd: ", err) |
| } |
| // Daisydog is the watchdog service. |
| cmd := `nohup sh -c 'sleep 2 |
| sync |
| stop daisydog |
| sleep 60 > /dev/watchdog' >/dev/null 2>&1 </dev/null &` |
| if err := h.DUT.Conn().CommandContext(ctx, "bash", "-c", cmd).Run(); err != nil { |
| s.Fatal("Failed to panic DUT: ", err) |
| } |
| s.Log("Waiting for DUT to become unreachable") |
| h.CloseRPCConnection(ctx) |
| |
| if err := h.DUT.WaitUnreachable(ctx); err != nil { |
| s.Fatal("Failed to wait for DUT to become unreachable: ", err) |
| } |
| s.Log("DUT became unreachable (as expected)") |
| |
| s.Log("Reconnecting to DUT") |
| shortCtx, cancel := context.WithTimeout(ctx, 60*time.Second) |
| defer cancel() |
| if err := h.WaitConnect(shortCtx); err != nil { |
| s.Fatal("Failed to reconnect to DUT: ", err) |
| } |
| s.Log("Reconnected to DUT") |
| } |
| events, err := r.EventlogListAfter(ctx, cutoffEvent) |
| if err != nil { |
| s.Fatal("Gathering events: ", err) |
| } |
| for _, event := range events { |
| s.Log("Found event: ", event) |
| } |
| |
| // Complicated rules here. |
| // One of the param.requiredEventSets must be found. |
| // Within that event set, all the regexs need to match to be considered found. |
| requiredEventsFound := false |
| for _, requiredEventSet := range param.requiredEventSets { |
| foundAllRequiredEventsInSet := true |
| for _, requiredEvent := range requiredEventSet { |
| reRequiredEvent := regexp.MustCompile(requiredEvent) |
| if !eventMessagesContainReMatch(ctx, events, reRequiredEvent) { |
| foundAllRequiredEventsInSet = false |
| break |
| } |
| } |
| if foundAllRequiredEventsInSet { |
| requiredEventsFound = true |
| break |
| } |
| } |
| if !requiredEventsFound { |
| s.Error("Required event missing") |
| } |
| if param.prohibitedEvents != "" { |
| reProhibitedEvents := regexp.MustCompile(param.prohibitedEvents) |
| var allowedRe *regexp.Regexp |
| if param.allowedEvents != "" { |
| allowedRe = regexp.MustCompile(param.allowedEvents) |
| } |
| for _, event := range events { |
| if reProhibitedEvents.MatchString(event.Message) && (allowedRe == nil || !allowedRe.MatchString(event.Message)) { |
| s.Errorf("Incorrect event logged: %+v", event) |
| } |
| } |
| } |
| } |
