diff --git a/doc/KUNIT.md b/doc/KUNIT.md index 1f8c4104e..f1b93ee00 100644 --- a/doc/KUNIT.md +++ b/doc/KUNIT.md @@ -173,8 +173,7 @@ sudo make kunit-run KUNIT_LABEL=TM KUNIT_ARGS='--verbose' Retain the complete printed run directory, especially `report.txt`, `result.json`, `messages.log`, `kernel.log`, `commands.log` and -`ktap/scst-TM-acg.ktap`. The companion TCP reproduction attempts are described -in the [component-test guide](../tests/ginkgo/README.md#issue-367-acg-reassignment). +`ktap/scst-TM-acg.ktap`. ## Add a suite diff --git a/tests/ginkgo/README.md b/tests/ginkgo/README.md index 766ddd210..ee870ee91 100644 --- a/tests/ginkgo/README.md +++ b/tests/ginkgo/README.md @@ -159,5 +159,5 @@ affected hosts before retrying; never remove a lock file to bypass a held lock. The printed artifact directory under `report_dir` contains effective config, command logs, JSON/JUnit reports and scenario inputs. I/O adds rendered jobs and fio results; iSCSI adds SSH, initiator and daemon logs, which may contain -test CHAP credentials. Kernel warnings are not collected: retain kernel logs -when investigating failures. +test CHAP credentials. Only the `issue-367` specs collect kernel warnings; +retain kernel logs separately when investigating other failures. diff --git a/tests/ginkgo/config.iscsi.example.json b/tests/ginkgo/config.iscsi.example.json index 1503ba28c..ffb34647d 100644 --- a/tests/ginkgo/config.iscsi.example.json +++ b/tests/ginkgo/config.iscsi.example.json @@ -8,6 +8,7 @@ "target_address": "192.0.2.10", "port": 3260, "login_timeout": "15s", + "acg_reassign_race": false, "initiator": { "host": "192.0.2.20", "user": "root", diff --git a/tests/ginkgo/internal/initiator/socket.go b/tests/ginkgo/internal/initiator/socket.go new file mode 100644 index 000000000..8581665f8 --- /dev/null +++ b/tests/ginkgo/internal/initiator/socket.go @@ -0,0 +1,37 @@ +// SPDX-License-Identifier: GPL-2.0-only +package initiator + +import ( + "fmt" + "net" + "strconv" + "strings" +) + +// TCPConnection parses ss -Hnt4 state established. With a single state and +// protocol selected, ss omits the State and Netid columns. Require exactly one +// connection to the fixture portal before constructing an exact reset filter. +func TCPConnection(output, portal string) (string, error) { + lines := strings.Split(strings.TrimSpace(output), "\n") + if len(lines) != 1 { + return "", fmt.Errorf("expected one TCP connection, got %d", len(lines)) + } + f := strings.Fields(lines[0]) + if len(f) != 4 || f[3] != portal { + return "", fmt.Errorf("unexpected ss connection: %q", output) + } + for _, queue := range f[:2] { + if _, err := strconv.ParseUint(queue, 10, 64); err != nil { + return "", fmt.Errorf("invalid ss queue: %q", queue) + } + } + host, port, err := net.SplitHostPort(f[2]) + if err != nil || net.ParseIP(host).To4() == nil || net.ParseIP(host).IsUnspecified() { + return "", fmt.Errorf("invalid local IPv4 endpoint: %q", f[2]) + } + n, err := strconv.Atoi(port) + if err != nil || n < 1 || n > 65535 { + return "", fmt.Errorf("invalid local TCP port: %q", port) + } + return f[2], nil +} diff --git a/tests/ginkgo/internal/initiator/socket_test.go b/tests/ginkgo/internal/initiator/socket_test.go new file mode 100644 index 000000000..16362af4e --- /dev/null +++ b/tests/ginkgo/internal/initiator/socket_test.go @@ -0,0 +1,26 @@ +// SPDX-License-Identifier: GPL-2.0-only +package initiator + +import "testing" + +func TestTCPConnection(t *testing.T) { + const portal = "192.0.2.10:3260" + const row = "0 12 192.0.2.20:45000 192.0.2.10:3260\n" + got, err := TCPConnection(row, portal) + if err != nil || got != "192.0.2.20:45000" { + t.Fatalf("connection = %q, %v", got, err) + } + for _, input := range []string{ + "", row + row, "ESTAB " + row, + "0 0 192.0.2.20:45000 192.0.2.11:3260", + "x 0 192.0.2.20:45000 " + portal, + "0 0 *:45000 " + portal, + "0 0 0.0.0.0:45000 " + portal, + "0 0 192.0.2.20:0 " + portal, + "0 0 192.0.2.20:65536 " + portal, + } { + if _, err := TCPConnection(input, portal); err == nil { + t.Errorf("accepted ambiguous or invalid socket: %q", input) + } + } +} diff --git a/tests/ginkgo/internal/testcfg/config.go b/tests/ginkgo/internal/testcfg/config.go index a93871b32..e4cd34f92 100644 --- a/tests/ginkgo/internal/testcfg/config.go +++ b/tests/ginkgo/internal/testcfg/config.go @@ -47,10 +47,11 @@ type IO struct { // ISCSI selects a local TCP target and a separate SSH initiator. Credentials // for test CHAP accounts are generated by the suite, never supplied here. type ISCSI struct { - TargetAddress string `json:"target_address"` - Port int `json:"port"` - LoginTimeout string `json:"login_timeout"` - Initiator Initiator `json:"initiator"` + TargetAddress string `json:"target_address"` + Port int `json:"port"` + LoginTimeout string `json:"login_timeout"` + ACGReassignRace bool `json:"acg_reassign_race"` + Initiator Initiator `json:"initiator"` } type Initiator struct { diff --git a/tests/ginkgo/internal/testcfg/config_test.go b/tests/ginkgo/internal/testcfg/config_test.go index 18448b833..b20a126fb 100644 --- a/tests/ginkgo/internal/testcfg/config_test.go +++ b/tests/ginkgo/internal/testcfg/config_test.go @@ -4,6 +4,7 @@ package testcfg import ( "os" "path/filepath" + "strings" "testing" ) @@ -88,9 +89,14 @@ func TestISCSIConfiguration(t *testing.T) { if err != nil { t.Fatal(err) } - if cfg.ISCSI.Initiator.DisposableHost || cfg.ISCSI.Initiator.IdentityFile != filepath.Join(filepath.Dir(path), "id_test") { + if cfg.ISCSI.ACGReassignRace || cfg.ISCSI.Initiator.DisposableHost || cfg.ISCSI.Initiator.IdentityFile != filepath.Join(filepath.Dir(path), "id_test") { t.Fatalf("unsafe defaults or bad path: %+v", cfg.ISCSI) } + optIn := strings.Replace(input, `"iscsi":{`, `"iscsi":{"acg_reassign_race":true,`, 1) + enabled, err := Load(configFile(t, optIn)) + if err != nil || !enabled.ISCSI.ACGReassignRace { + t.Fatalf("explicit race selection lost: %+v, %v", enabled.ISCSI, err) + } for name, change := range map[string]func(*ISCSI){ "wildcard target": func(i *ISCSI) { i.TargetAddress = "0.0.0.0" }, "localhost": func(i *ISCSI) { i.TargetAddress = "127.0.0.1" }, diff --git a/tests/ginkgo/internal/testhost/kernel_log.go b/tests/ginkgo/internal/testhost/kernel_log.go new file mode 100644 index 000000000..0857c7900 --- /dev/null +++ b/tests/ginkgo/internal/testhost/kernel_log.go @@ -0,0 +1,215 @@ +// SPDX-License-Identifier: GPL-2.0-only +package testhost + +import ( + "context" + "errors" + "fmt" + "io" + "os" + "regexp" + "strconv" + "strings" + "sync" + "syscall" + "time" +) + +var kernelFault = regexp.MustCompile(`(?i)WARNING:|BUG:|Oops:|Kernel panic|KASAN:|KCSAN:|UBSAN:|kernel BUG at|general protection fault|Unable to handle kernel|Call [Tt]race:|Backtrace:|(?:soft|hard) LOCKUP|blocked for more than|rcu:.*stall`) + +// KernelLog captures new records only. A read/sequence error or diagnostic is +// sticky: callers must preserve the target instead of starting teardown. +type KernelLog struct { + mu sync.Mutex + read func([]byte) (int, error) + output io.Writer + sequence uint64 + seen bool + err error + stop chan struct{} + done chan struct{} + close func() error + watches map[*KernelWatch]struct{} +} + +// KernelMessage identifies a LOG_KERN record in the raw capture. Microseconds +// is the kernel timestamp, not a wall-clock time comparable to command logs. +type KernelMessage struct { + Sequence uint64 + Microseconds uint64 + Text string +} + +// KernelWatch matches only new messages after Watch drained the existing log. +// Its fields are protected by the capture's mutex, including background reads. +type KernelWatch struct { + kernel *KernelLog + contains string + match *KernelMessage +} + +func (k *KernelLog) Watch(contains string) (*KernelWatch, error) { + k.mu.Lock() + defer k.mu.Unlock() + if contains == "" { + return nil, fmt.Errorf("empty kernel message filter") + } + if err := k.check(); err != nil { + return nil, err + } + w := &KernelWatch{kernel: k, contains: contains} + if k.watches == nil { + k.watches = make(map[*KernelWatch]struct{}) + } + k.watches[w] = struct{}{} + return w, nil +} + +func (w *KernelWatch) Close() { + w.kernel.mu.Lock() + defer w.kernel.mu.Unlock() + delete(w.kernel.watches, w) +} + +// Wait checks the whole batch before accepting a match: a diagnostic or lost +// record in that batch must not authorize another test operation. +func (w *KernelWatch) Wait(ctx context.Context) (KernelMessage, error) { + ticker := time.NewTicker(time.Millisecond) + defer ticker.Stop() + for { + if err := ctx.Err(); err != nil { + return KernelMessage{}, err + } + w.kernel.mu.Lock() + err := w.kernel.check() + match := w.match + w.kernel.mu.Unlock() + if err != nil { + return KernelMessage{}, err + } + if match != nil { + return *match, nil + } + select { + case <-ctx.Done(): + return KernelMessage{}, ctx.Err() + case <-ticker.C: + } + } +} + +func StartKernelLog(path string) (*KernelLog, error) { + fd, err := syscall.Open("/dev/kmsg", syscall.O_RDONLY|syscall.O_NONBLOCK|syscall.O_CLOEXEC, 0) + if err != nil { + return nil, err + } + if _, err := syscall.Seek(fd, 0, io.SeekEnd); err != nil { + syscall.Close(fd) + return nil, err + } + log, err := os.OpenFile(path, os.O_CREATE|os.O_EXCL|os.O_WRONLY, 0600) + if err != nil { + syscall.Close(fd) + return nil, err + } + k := &KernelLog{ + read: func(p []byte) (int, error) { return syscall.Read(fd, p) }, output: log, + stop: make(chan struct{}), done: make(chan struct{}), + close: func() error { return errors.Join(syscall.Close(fd), log.Close()) }, + } + go func() { + defer close(k.done) + ticker := time.NewTicker(20 * time.Millisecond) + defer ticker.Stop() + for { + select { + case <-ticker.C: + k.Check() + case <-k.stop: + k.Check() + return + } + } + }() + return k, nil +} + +// Check drains a bounded batch even after a fault, retaining subsequent trace +// records. The bound also prevents a noisy kernel from delaying test deadlines. +func (k *KernelLog) Check() error { + k.mu.Lock() + defer k.mu.Unlock() + return k.check() +} + +// check requires mu; Watch uses it to drain and arm without an intervening read. +func (k *KernelLog) check() error { + buffer := make([]byte, 64*1024) + for i := 0; i < 256; i++ { + n, err := k.read(buffer) + if errors.Is(err, syscall.EAGAIN) { + return k.err + } + if err == nil && n == 0 { + err = io.ErrUnexpectedEOF + } + if err != nil { + if k.err == nil { + k.err = err + } + return k.err + } + if err := k.accept(buffer[:n]); err != nil && k.err == nil { + k.err = err + } + } + if k.err == nil { + k.err = fmt.Errorf("kernel log backlog exceeds capture limit; evidence incomplete") + } + return k.err +} + +func (k *KernelLog) accept(record []byte) error { + if n, err := k.output.Write(record); err != nil { + return err + } else if n != len(record) { + return io.ErrShortWrite + } + header, body, ok := strings.Cut(string(record), ";") + fields := strings.Split(header, ",") + if !ok || len(fields) < 4 { + return fmt.Errorf("malformed /dev/kmsg record") + } + priority, pErr := strconv.ParseUint(fields[0], 10, 32) + sequence, sErr := strconv.ParseUint(fields[1], 10, 64) + microseconds, tErr := strconv.ParseUint(fields[2], 10, 64) + if pErr != nil || sErr != nil || tErr != nil { + return fmt.Errorf("invalid /dev/kmsg metadata") + } + lost := k.seen && sequence != k.sequence+1 + k.sequence, k.seen = sequence, true + if lost { + return fmt.Errorf("lost kernel records before sequence %d", sequence) + } + // Userspace records remain in the artifact but cannot supply LOG_KERN + // diagnostics. Ignore dictionary properties following the message line. + message, _, _ := strings.Cut(body, "\n") + if priority>>3 == 0 { + if kernelFault.MatchString(message) { + return fmt.Errorf("kernel diagnostic: %s", message) + } + for w := range k.watches { + if strings.Contains(message, w.contains) { + w.match = &KernelMessage{Sequence: sequence, Microseconds: microseconds, Text: message} + delete(k.watches, w) + } + } + } + return nil +} + +func (k *KernelLog) Close() error { + close(k.stop) + <-k.done + return errors.Join(k.err, k.close()) +} diff --git a/tests/ginkgo/internal/testhost/kernel_log_test.go b/tests/ginkgo/internal/testhost/kernel_log_test.go new file mode 100644 index 000000000..b7056c5e7 --- /dev/null +++ b/tests/ginkgo/internal/testhost/kernel_log_test.go @@ -0,0 +1,180 @@ +// SPDX-License-Identifier: GPL-2.0-only +package testhost + +import ( + "bytes" + "context" + "errors" + "io" + "strings" + "syscall" + "testing" + "time" +) + +func TestKernelLogEvidence(t *testing.T) { + for _, tc := range []struct { + name string + rows []string + want string + }{ + {"normal", []string{"6,41,100,-;scst session reassigned\n", "6,42,101,-;done\n"}, ""}, + {"userspace", []string{"14,1,1,-;BUG: userspace text\n"}, ""}, + {"oops", []string{"3,1,1,-;BUG: kernel NULL pointer dereference\n", "3,2,2,-;Call Trace:\n", "3,3,3,-; scst_tm_thread+0x10\n"}, "kernel diagnostic"}, + {"warning", []string{"4,1,1,-;WARNING: CPU: 0\n"}, "kernel diagnostic"}, + {"gap", []string{"6,1,1,-;a\n", "6,3,2,-;b\n"}, "lost kernel records"}, + {"malformed", []string{"bad record\n"}, "malformed"}, + {"metadata", []string{"6,x,1,-;bad\n"}, "invalid"}, + } { + t.Run(tc.name, func(t *testing.T) { + var output bytes.Buffer + rows := append([]string(nil), tc.rows...) + k := &KernelLog{output: &output, read: func(p []byte) (int, error) { + if len(rows) == 0 { + return 0, syscall.EAGAIN + } + n := copy(p, rows[0]) + rows = rows[1:] + return n, nil + }} + err := k.Check() + if tc.want == "" && err != nil || tc.want != "" && (err == nil || !strings.Contains(err.Error(), tc.want)) { + t.Fatalf("Check() = %v, wanted %q", err, tc.want) + } + if k.Check() != err { + t.Fatal("failure was not retained") + } + if output.String() != strings.Join(tc.rows, "") { + t.Fatal("raw evidence lost") + } + }) + } +} + +func TestKernelLogReadFailures(t *testing.T) { + for _, readErr := range []error{syscall.EPIPE, io.ErrUnexpectedEOF} { + k := &KernelLog{output: io.Discard, read: func([]byte) (int, error) { return 0, readErr }} + if !errors.Is(k.Check(), readErr) { + t.Fatal("read failure was accepted") + } + } +} + +func kernelWatchFixture() (*KernelLog, chan string) { + rows := make(chan string, 16) + k := &KernelLog{output: io.Discard, read: func(p []byte) (int, error) { + select { + case row := <-rows: + return copy(p, row), nil + default: + return 0, syscall.EAGAIN + } + }} + return k, rows +} + +func TestKernelWatchFreshKernelMessage(t *testing.T) { + k, rows := kernelWatchFixture() + const message = "(initiator iqn.test:ours) will be reassigned from acg access to acg alternate" + rows <- "6,1,100,-;scst: " + message + "\n" + w, err := k.Watch(message) + if err != nil { + t.Fatal(err) + } + defer w.Close() + rows <- "14,2,101,-;scst: " + message + "\n" + rows <- "6,3,102,-;scst: (initiator iqn.test:other) will be reassigned from acg access to acg alternate\n" + rows <- "6,4,103,-;unrelated\n PROPERTY=" + message + "\n" + rows <- "6,5,104,-;scst: " + message + "\n" + rows <- "6,6,105,-;scst: " + message + "\n" + // The background collector may see the message before Wait starts. + if err := k.Check(); err != nil { + t.Fatal(err) + } + ctx, cancel := context.WithTimeout(context.Background(), time.Second) + defer cancel() + got, err := w.Wait(ctx) + if err != nil || got.Sequence != 5 || got.Microseconds != 104 || got.Text != "scst: "+message { + t.Fatalf("Wait() = %+v, %v; want first fresh kernel message at sequence 5", got, err) + } +} + +func TestKernelWatchRejectsIncompleteEvidence(t *testing.T) { + for _, tc := range []struct { + name string + rows []string + want string + }{ + {"fault after match", []string{"6,1,1,-;ready\n", "4,2,2,-;WARNING: CPU: 0\n"}, "kernel diagnostic"}, + {"fault before match", []string{"3,1,1,-;BUG: kernel NULL pointer dereference\n", "6,2,2,-;ready\n"}, "kernel diagnostic"}, + {"lost records", []string{"6,1,1,-;unrelated\n", "6,3,3,-;ready\n"}, "lost kernel records"}, + {"malformed after match", []string{"6,1,1,-;ready\n", "bad record\n"}, "malformed"}, + } { + t.Run(tc.name, func(t *testing.T) { + k, rows := kernelWatchFixture() + w, err := k.Watch("ready") + if err != nil { + t.Fatal(err) + } + defer w.Close() + for _, row := range tc.rows { + rows <- row + } + ctx, cancel := context.WithTimeout(context.Background(), time.Second) + defer cancel() + if _, err := w.Wait(ctx); err == nil || !strings.Contains(err.Error(), tc.want) { + t.Fatalf("Wait() = %v, want %s", err, tc.want) + } + if _, err := k.Watch("another operation"); err == nil { + t.Fatal("armed another watch after incomplete evidence") + } + }) + } +} + +func TestKernelWatchDeadlineAndCancellation(t *testing.T) { + for _, canceled := range []bool{false, true} { + k, rows := kernelWatchFixture() + w, err := k.Watch("ready") + if err != nil { + t.Fatal(err) + } + ctx, cancel := context.WithTimeout(context.Background(), 10*time.Millisecond) + want := context.DeadlineExceeded + if canceled { + rows <- "6,1,1,-;ready\n" + cancel() + want = context.Canceled + } + _, err = w.Wait(ctx) + cancel() + w.Close() + if !errors.Is(err, want) { + t.Fatalf("Wait() = %v, want %v", err, want) + } + if len(k.watches) != 0 { + t.Fatal("closed watch still registered") + } + } +} + +func TestKernelWatchConcurrentCapture(t *testing.T) { + k, rows := kernelWatchFixture() + w, err := k.Watch("ready") + if err != nil { + t.Fatal(err) + } + defer w.Close() + done := make(chan error, 1) + go func() { + rows <- "6,1,1,-;ready\n" + done <- k.Check() + }() + ctx, cancel := context.WithTimeout(context.Background(), time.Second) + defer cancel() + got, err := w.Wait(ctx) + captureErr := <-done + if err != nil || captureErr != nil || got.Sequence != 1 { + t.Fatalf("Wait() = %+v, %v; capture error = %v", got, err, captureErr) + } +} diff --git a/tests/ginkgo/iscsi/acg_reassign_test.go b/tests/ginkgo/iscsi/acg_reassign_test.go new file mode 100644 index 000000000..031c335a5 --- /dev/null +++ b/tests/ginkgo/iscsi/acg_reassign_test.go @@ -0,0 +1,181 @@ +// SPDX-License-Identifier: GPL-2.0-only +package iscsi + +import ( + "context" + "fmt" + "net" + "path/filepath" + "strconv" + + . "github.com/onsi/ginkgo/v2" + . "github.com/onsi/gomega" + + "scst-component-tests/internal/admin" + "scst-component-tests/internal/initiator" + "scst-component-tests/internal/testcfg" + "scst-component-tests/internal/testhost" +) + +const ( + alternateACG = "alternate" + // Both directions replace tgt_devs while retaining the bootstrapping LUN 0. + reassignLUNs = 16 +) + +func (f *fixture) expectLUNs(ctx context.Context, luns map[int]string) { + GinkgoHelper() + Eventually(func(g Gomega) { + sessions, err := cli.SessionDetails(ctx) + g.Expect(err).NotTo(HaveOccurred()) + g.Expect(sessions["iscsi/"+f.Target]).To(HaveLen(1)) + for _, s := range sessions["iscsi/"+f.Target] { + g.Expect(s.LUNs).To(Equal(luns)) + } + }, testcfg.Duration(cfg.SettleTimeout), testcfg.Duration(cfg.PollInterval)).WithContext(ctx).Should(Succeed()) +} + +func fixtureSocket(ctx context.Context) string { + GinkgoHelper() + r := remoteOK(ctx, "ss", "-Hnt4", "state", "established", "dst", cfg.ISCSI.TargetAddress, + "dport", "=", fmt.Sprint(cfg.ISCSI.Port)) + return must(initiator.TCPConnection(r.Stdout, portal())) +} + +type acgMoveResult struct { + command admin.Result + err error +} + +// No Ginkgo assertions run in the worker. Its caller always joins it before +// asserting or cleaning up, including when the initiator command failed. +func (f *fixture) raceACG(ctx context.Context, kernel *testhost.KernelLog, from, to string, argv []string, resetSocket string) { + GinkgoHelper() + watch := must(kernel.Watch(fmt.Sprintf("(initiator %s) will be reassigned from acg %s to acg %s", f.Initiator, from, to))) + defer watch.Close() + done := make(chan acgMoveResult, 1) + go func() { + r, err := cli.Execute(ctx, "-move_init", f.Initiator, "-driver", "iscsi", "-target", f.Target, + "-group", from, "-to", to) + done <- acgMoveResult{command: r, err: err} + }() + // Starting both userspace commands together mostly measures CLI/SSH startup. + // Wait for this session to enter reassignment before requesting teardown. + waitCtx, cancel := context.WithTimeout(ctx, testcfg.Duration(cfg.CommandTimeout)) + message, waitErr := watch.Wait(waitCtx) + cancel() + var r admin.Result + var err error + if waitErr == nil { + r, err = peer.Run(ctx, testcfg.Duration(cfg.CommandTimeout), argv...) + } + move := <-done + Expect(kernel.Check()).To(Succeed()) + Expect(move.err).NotTo(HaveOccurred(), move.command.String()) + Expect(move.command.ExitCode).To(BeZero(), move.command.String()) + Expect(move.command.ReportedError()).To(BeFalse(), move.command.String()) + Expect(waitErr).NotTo(HaveOccurred(), "no fresh reassignment message for the fixture; teardown was not requested") + AddReportEntry("reassignment", fmt.Sprintf("%s -> %s; kernel sequence=%d time_us=%d; move=%s; teardown=%s", + from, to, message.Sequence, message.Microseconds, move.command.Duration, r.Duration)) + Expect(err).NotTo(HaveOccurred(), r.String()) + Expect(r.ExitCode).To(BeZero(), r.String()) + if argv[0] == "ss" { + // ss -K may exit zero without destroying a socket, e.g. if the kernel + // lacks SOCK_DESTROY support. Its output must identify our exact tuple. + Expect(r.Stderr).To(BeEmpty(), r.String()) + local := must(initiator.TCPConnection(r.Stdout, portal())) + Expect(local).To(Equal(resetSocket)) + } + Expect(r.Started.Before(move.command.Started.Add(move.command.Duration))).To(BeTrue(), + "ACG move completed before teardown started; this round is inconclusive") +} + +var _ = DescribeTable("ACG reassignment during iSCSI teardown", Label("iscsi", "stress", "sessions", "issue-367"), + func(ctx SpecContext, recoverTCP bool) { + if !cfg.ISCSI.ACGReassignRace { + Skip("set iscsi.acg_reassign_race=true on disposable VMs to attempt issue #367") + } + path := filepath.Join(artifactDir, fmt.Sprintf("issue-367-%t-kernel.log", recoverTCP)) + kernel := must(testhost.StartKernelLog(path)) + AddReportEntry("kernel log", path) + // Registered before the fixture: capture remains active throughout its + // cleanup. On diagnostic/error, prevent suite-level module unloading. + DeferCleanup(func() { + if err := kernel.Close(); err != nil { + pending.Add(1) + AbortSuite("kernel evidence failed; preserve target stack: " + err.Error()) + } + }) + f := newFixture(ctx) + f.beforeCleanup = kernel.Check + f.at(ctx, "", "-add_group", alternateACG) + // Disjoint nonzero LUN maps exercise allocation AND removal on every + // round. A single extra LUN only exercises removal in one direction. + f.at(ctx, alternateACG, "-add_lun", "0", "-device", f.Device) + alternateLUNs := map[int]string{0: f.Device} + for lun := 1; lun <= reassignLUNs; lun++ { + f.at(ctx, "access", "-add_lun", strconv.Itoa(lun), "-device", f.Device) + f.LUNs[lun] = f.Device + f.at(ctx, alternateACG, "-add_lun", strconv.Itoa(lun+reassignLUNs), "-device", f.Device) + alternateLUNs[lun+reassignLUNs] = f.Device + } + maps := map[string]map[int]string{"access": f.LUNs, alternateACG: alternateLUNs} + AddReportEntry("ACG maps", maps) + f.login(ctx) + f.at(ctx, "access", "-move_init", f.Initiator, "-to", alternateACG) + f.expectLUNs(ctx, alternateLUNs) + f.at(ctx, alternateACG, "-move_init", f.Initiator, "-to", "access") + f.expectLUNs(ctx, f.LUNs) + f.logout(ctx) + + from, to := "access", alternateACG + for i := 0; i < cfg.StressIterations; i++ { + By(fmt.Sprintf("round %d: %s -> %s, TCP recovery=%t", i+1, from, to, recoverTCP)) + Expect(kernel.Check()).To(Succeed()) + f.login(ctx) + argv := []string{"iscsiadm", "-m", "node", "-T", f.Target, "-p", portal(), "-I", f.Iface, "--logout"} + var before string + var sessionID string + if recoverTCP { + before = fixtureSocket(ctx) + sessions := must(initiator.Sessions(remoteOK(ctx, "iscsiadm", "-m", "session").Stdout)) + Expect(sessions).To(HaveLen(1)) + Expect(sessions[0].Target).To(Equal(f.Target)) + sessionID = sessions[0].ID + host, port, err := net.SplitHostPort(before) + Expect(err).NotTo(HaveOccurred()) + argv = []string{"ss", "-K", "-Hnt4", "state", "established", "src", host, "sport", "=", port, + "dst", cfg.ISCSI.TargetAddress, "dport", "=", fmt.Sprint(cfg.ISCSI.Port)} + } + f.raceACG(ctx, kernel, from, to, argv, before) + f.LUNs = maps[to] + if recoverTCP { + Eventually(func(g Gomega) { + g.Expect(kernel.Check()).To(Succeed()) + r := remoteOK(ctx, "ss", "-Hnt4", "state", "established", "dst", cfg.ISCSI.TargetAddress, + "dport", "=", fmt.Sprint(cfg.ISCSI.Port)) + local, err := initiator.TCPConnection(r.Stdout, portal()) + g.Expect(err).NotTo(HaveOccurred()) + g.Expect(local).NotTo(Equal(before), "require a replacement TCP connection") + r = remoteOK(ctx, "iscsiadm", "-m", "session", "-r", sessionID, "-P", "1") + g.Expect(r.Stdout).To(MatchRegexp(`(?m)^\s*iSCSI Connection State: LOGGED IN\s*$`)) + }, testcfg.Duration(cfg.CommandTimeout), testcfg.Duration(cfg.PollInterval)).WithContext(ctx).Should(Succeed()) + f.expectLUNs(ctx, f.LUNs) + f.logout(ctx) + } else { + expectNoSessions(ctx) + f.noTargetSession(ctx) + } + assignments := must(cli.DriverAssignments(ctx, "iscsi", f.Target)) + Expect(assignments.Groups[to].Initiators).To(ConsistOf(f.Initiator)) + Expect(assignments.Groups[from].Initiators).To(BeEmpty()) + Expect(kernel.Check()).To(Succeed()) + from, to = to, from + } + // Successful commands and clean logs cannot establish that the TM + // reader entered the short NULL-ACG window on any particular round. + AddReportEntry("issue #367 outcome", fmt.Sprintf("not reproduced in %d kernel-observed reassignments; TM/NULL-ACG overlap was not observed directly", cfg.StressIterations)) + }, + Entry("with logout", false), + Entry("with TCP connection recovery", true), +) diff --git a/tests/ginkgo/iscsi/fixture_test.go b/tests/ginkgo/iscsi/fixture_test.go index 3f8d2ae2f..33106132a 100644 --- a/tests/ginkgo/iscsi/fixture_test.go +++ b/tests/ginkgo/iscsi/fixture_test.go @@ -25,6 +25,7 @@ type fixture struct { BackingFiles []string Target, Initiator, Iface, Device string ifaceOwned, nodeOwned, targetOwned, deviceOwned bool + beforeCleanup func() error } var sequence int @@ -196,6 +197,9 @@ func (f *fixture) logout(ctx context.Context) { func (f *fixture) cleanup(ctx context.Context) { GinkgoHelper() + if f.beforeCleanup != nil { + Expect(f.beforeCleanup()).To(Succeed(), "preserving fixture after kernel diagnostic or lost evidence") + } Expect(peer.Blocked()).NotTo(HaveOccurred(), "preserving target while initiator state is uncertain") Expect(cli.Blocked()).NotTo(HaveOccurred()) Expect(daemon.Running()).To(Succeed())