From bc2767c87c4090798c4c7d15e101ed066e947301 Mon Sep 17 00:00:00 2001 From: Paul Buetow Date: Wed, 22 Jul 2026 23:51:28 +0300 Subject: =?UTF-8?q?test:=20DTail=20fork=20=E2=80=94=20integration=20test?= =?UTF-8?q?=20suite=20and=20fixtures?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Squashed development of the integration test suite (integrationtests/) covering DCat, DGrep, DMap (serverless + server mode), DTail follow, DServer, DTailHealth, journal source reads, auth-key fast reconnect, interactive query reload, client-deadline/timeout behaviour, and the single-mode read/output path. Includes real test fixtures (dserver*.cfg, dmap_csv_multifile_*.csv.in, test_server_*.json, *.expected golden files) and deterministic synchronization helpers (waitContains-style barriers) replacing racy fixed-timing assertions. Accidental debug/output dumps that earlier commits added here (captured client output, strace logs, ad-hoc turbo_test_output/manual_output/test_output files, throwaway debug scripts) are intentionally excluded and gitignored. Co-Authored-By: Claude Opus 4.8 --- integrationtests/authkey_test.go | 467 ++ integrationtests/commandutils.go | 80 +- integrationtests/dcat1d.txt | 1 - integrationtests/dcat_logpayload_test.go | 141 + integrationtests/dcat_test.go | 428 +- integrationtests/dcatcolors.expected | 5507 ++++++++++---------- integrationtests/dcatcolors.server.expected | 2754 ++++++++++ integrationtests/dgrep2.txt.expected | 585 +-- integrationtests/dgrep_literal_info_test.go | 191 + integrationtests/dgrep_literal_regex_test.go | 392 ++ integrationtests/dgrep_test.go | 645 ++- integrationtests/dgrepcontext1.txt.expected | 1 - integrationtests/dgrepcontext2.txt.expected | 594 +++ integrationtests/djournal_extended_test.go | 1028 ++++ integrationtests/djournal_test.go | 380 ++ integrationtests/dmap4.csv.expected | 407 -- integrationtests/dmap4.csv.query.expected | 1 - integrationtests/dmap4_query1.csv.expected | 204 + integrationtests/dmap4_query3.csv.expected | 2 + integrationtests/dmap_csv_multifile.csv.expected | 2 + integrationtests/dmap_csv_multifile_a.csv.in | 3 + integrationtests/dmap_csv_multifile_b.csv.in | 4 + integrationtests/dmap_csv_multifile_test.go | 92 + integrationtests/dmap_large_test.go | 266 + integrationtests/dmap_multiserver_test.go | 108 + integrationtests/dmap_test.go | 754 ++- integrationtests/dserver1.cfg | 2 +- integrationtests/dserver1.csv.query.expected | 2 +- integrationtests/dserver2.cfg | 4 +- integrationtests/dserver2.csv.query.expected | 2 +- integrationtests/dserver_test.go | 39 +- integrationtests/dtail_test.go | 199 +- integrationtests/dtail_timeout_test.go | 136 + integrationtests/dtailhealth_test.go | 215 +- integrationtests/fileutils.go | 27 +- integrationtests/interactive_runtime_query_test.go | 535 ++ .../runtime_query_compatibility_test.go | 260 + integrationtests/test_server_100files.json | 8 + integrationtests/test_server_complete.json | 8 + integrationtests/testhelpers.go | 505 ++ 40 files changed, 12982 insertions(+), 3997 deletions(-) create mode 100644 integrationtests/authkey_test.go delete mode 100644 integrationtests/dcat1d.txt create mode 100644 integrationtests/dcat_logpayload_test.go create mode 100644 integrationtests/dcatcolors.server.expected create mode 100644 integrationtests/dgrep_literal_info_test.go create mode 100644 integrationtests/dgrep_literal_regex_test.go create mode 100644 integrationtests/djournal_extended_test.go create mode 100644 integrationtests/djournal_test.go delete mode 100644 integrationtests/dmap4.csv.expected delete mode 100644 integrationtests/dmap4.csv.query.expected create mode 100644 integrationtests/dmap4_query1.csv.expected create mode 100644 integrationtests/dmap4_query3.csv.expected create mode 100644 integrationtests/dmap_csv_multifile.csv.expected create mode 100644 integrationtests/dmap_csv_multifile_a.csv.in create mode 100644 integrationtests/dmap_csv_multifile_b.csv.in create mode 100644 integrationtests/dmap_csv_multifile_test.go create mode 100644 integrationtests/dmap_large_test.go create mode 100644 integrationtests/dmap_multiserver_test.go create mode 100644 integrationtests/dtail_timeout_test.go create mode 100644 integrationtests/interactive_runtime_query_test.go create mode 100644 integrationtests/runtime_query_compatibility_test.go create mode 100644 integrationtests/test_server_100files.json create mode 100644 integrationtests/test_server_complete.json create mode 100644 integrationtests/testhelpers.go (limited to 'integrationtests') diff --git a/integrationtests/authkey_test.go b/integrationtests/authkey_test.go new file mode 100644 index 0000000..3e5e7e4 --- /dev/null +++ b/integrationtests/authkey_test.go @@ -0,0 +1,467 @@ +package integrationtests + +import ( + "context" + "crypto/rand" + "crypto/rsa" + "crypto/x509" + "encoding/pem" + "fmt" + "os" + "path/filepath" + "strings" + "sync" + "testing" + "time" + + gossh "golang.org/x/crypto/ssh" +) + +const ( + authKeyFastPathLog = "Authorized by in-memory auth key store" + dcatExpectedFirstOutput = "1 Sat 2 Oct 13:46:45 EEST 2021" +) + +func TestAuthKeyFastReconnectIntegration(t *testing.T) { + skipIfNotIntegrationTest(t) + cleanupTmpFiles(t) + + t.Run("RegistrationFastPathAndFallback", testAuthKeyRegistrationFastPathAndFallback) + t.Run("TTLExpiry", testAuthKeyTTLExpiry) + t.Run("MaxKeysPerUser", testAuthKeyMaxKeysPerUser) + t.Run("NoAuthKeyFlag", testNoAuthKeyFlagDisablesFeature) + t.Run("PassphraseProtectedKey", testPassphraseKeyAuthKeyRegistrationAndFastReconnect) +} + +func testAuthKeyRegistrationFastPathAndFallback(t *testing.T) { + authKeyPath := createAuthKeyPair(t, "authkey-registration") + server := startAuthKeyServer(t, "") + defer server.Stop() + + exitCode, err := runDCatWithAuthKey(server.Context(), t, "authkey_registration_1.tmp", server.Address(), authKeyPath, false) + if err != nil || exitCode != 0 { + t.Fatalf("Expected first connection to succeed, exit=%d err=%v", exitCode, err) + } + assertDCatSuccessfulOutput(t, "authkey_registration_1.tmp") + waitForServerLogs() + if got := server.CountLogLinesContaining(authKeyFastPathLog); got != 0 { + t.Fatalf("Expected first connection to use fallback, fast-path count=%d", got) + } + + exitCode, err = runDCatWithAuthKey(server.Context(), t, "authkey_registration_2.tmp", server.Address(), authKeyPath, false) + if err != nil || exitCode != 0 { + t.Fatalf("Expected second connection to succeed, exit=%d err=%v", exitCode, err) + } + assertDCatSuccessfulOutput(t, "authkey_registration_2.tmp") + waitForServerLogs() + if got := server.CountLogLinesContaining(authKeyFastPathLog); got < 1 { + t.Fatalf("Expected fast-path authorization after registration, fast-path count=%d", got) + } + + server.Stop() + time.Sleep(300 * time.Millisecond) + + restartedServer := startAuthKeyServer(t, "") + defer restartedServer.Stop() + + exitCode, err = runDCatWithAuthKey(restartedServer.Context(), t, "authkey_registration_3.tmp", restartedServer.Address(), authKeyPath, false) + if err != nil || exitCode != 0 { + t.Fatalf("Expected fallback after restart to succeed, exit=%d err=%v", exitCode, err) + } + assertDCatSuccessfulOutput(t, "authkey_registration_3.tmp") + waitForServerLogs() + if got := restartedServer.CountLogLinesContaining(authKeyFastPathLog); got != 0 { + t.Fatalf("Expected no fast-path hit on first post-restart connection, fast-path count=%d", got) + } +} + +func testAuthKeyTTLExpiry(t *testing.T) { + authKeyPath := createAuthKeyPair(t, "authkey-ttl") + ttlSeconds := 8 + cfgFile := writeAuthKeyServerConfig(t, ttlSeconds, 5) + server := startAuthKeyServer(t, cfgFile) + defer server.Stop() + + exitCode, err := runDCatWithAuthKey(server.Context(), t, "authkey_ttl_1.tmp", server.Address(), authKeyPath, false) + if err != nil || exitCode != 0 { + t.Fatalf("Expected first connection to succeed, exit=%d err=%v", exitCode, err) + } + assertDCatSuccessfulOutput(t, "authkey_ttl_1.tmp") + + exitCode, err = runDCatWithAuthKey(server.Context(), t, "authkey_ttl_2.tmp", server.Address(), authKeyPath, false) + if err != nil || exitCode != 0 { + t.Fatalf("Expected second connection to succeed, exit=%d err=%v", exitCode, err) + } + assertDCatSuccessfulOutput(t, "authkey_ttl_2.tmp") + fastPathCountAfterSecond := waitForLogCountAtLeast(server, authKeyFastPathLog, 1, 5*time.Second) + if fastPathCountAfterSecond < 1 { + t.Fatalf("Expected fast-path hit before TTL expiry, count=%d\nserver logs:\n%s", + fastPathCountAfterSecond, strings.Join(server.LogLines(), "\n")) + } + + time.Sleep(time.Duration(ttlSeconds+1) * time.Second) + exitCode, err = runDCatWithAuthKey(server.Context(), t, "authkey_ttl_3.tmp", server.Address(), authKeyPath, false) + if err != nil || exitCode != 0 { + t.Fatalf("Expected fallback after TTL expiry to still connect, exit=%d err=%v", exitCode, err) + } + assertDCatSuccessfulOutput(t, "authkey_ttl_3.tmp") + waitForServerLogs() + fastPathCountAfterThird := server.CountLogLinesContaining(authKeyFastPathLog) + if fastPathCountAfterThird != fastPathCountAfterSecond { + t.Fatalf("Expected TTL-expired key to stop fast-path hits: before=%d after=%d", + fastPathCountAfterSecond, fastPathCountAfterThird) + } +} + +func testAuthKeyMaxKeysPerUser(t *testing.T) { + authKeyOne := createAuthKeyPair(t, "authkey-max-one") + authKeyTwo := createAuthKeyPair(t, "authkey-max-two") + cfgFile := writeAuthKeyServerConfig(t, 3600, 1) + server := startAuthKeyServer(t, cfgFile) + defer server.Stop() + + if exitCode, err := runDCatWithAuthKey(server.Context(), t, "authkey_max_1.tmp", server.Address(), authKeyOne, false); err != nil || exitCode != 0 { + t.Fatalf("Expected first key registration to succeed, exit=%d err=%v", exitCode, err) + } + assertDCatSuccessfulOutput(t, "authkey_max_1.tmp") + if exitCode, err := runDCatWithAuthKey(server.Context(), t, "authkey_max_2.tmp", server.Address(), authKeyTwo, false); err != nil || exitCode != 0 { + t.Fatalf("Expected second key registration to succeed, exit=%d err=%v", exitCode, err) + } + assertDCatSuccessfulOutput(t, "authkey_max_2.tmp") + waitForServerLogs() + initialFastPathCount := server.CountLogLinesContaining(authKeyFastPathLog) + + if exitCode, err := runDCatWithAuthKey(server.Context(), t, "authkey_max_3.tmp", server.Address(), authKeyOne, false); err != nil || exitCode != 0 { + t.Fatalf("Expected first key connection (after max eviction) to succeed via fallback, exit=%d err=%v", exitCode, err) + } + assertDCatSuccessfulOutput(t, "authkey_max_3.tmp") + waitForServerLogs() + afterOldKeyCount := server.CountLogLinesContaining(authKeyFastPathLog) + if afterOldKeyCount != initialFastPathCount { + t.Fatalf("Expected evicted old key to avoid fast-path hit: before=%d after=%d", + initialFastPathCount, afterOldKeyCount) + } + + if exitCode, err := runDCatWithAuthKey(server.Context(), t, "authkey_max_4.tmp", server.Address(), authKeyOne, false); err != nil || exitCode != 0 { + t.Fatalf("Expected re-registered first key to succeed, exit=%d err=%v", exitCode, err) + } + assertDCatSuccessfulOutput(t, "authkey_max_4.tmp") + waitForServerLogs() + afterNewKeyCount := server.CountLogLinesContaining(authKeyFastPathLog) + if afterNewKeyCount <= afterOldKeyCount { + t.Fatalf("Expected re-registered key to use fast-path: old-count=%d new-count=%d", afterOldKeyCount, afterNewKeyCount) + } +} + +func testNoAuthKeyFlagDisablesFeature(t *testing.T) { + authKeyPath := createAuthKeyPair(t, "authkey-noauth") + server := startAuthKeyServer(t, "") + defer server.Stop() + + if exitCode, err := runDCatWithAuthKey(server.Context(), t, "authkey_noauth_1.tmp", server.Address(), authKeyPath, true); err != nil || exitCode != 0 { + t.Fatalf("Expected first --no-auth-key connection to succeed, exit=%d err=%v", exitCode, err) + } + assertDCatSuccessfulOutput(t, "authkey_noauth_1.tmp") + if exitCode, err := runDCatWithAuthKey(server.Context(), t, "authkey_noauth_2.tmp", server.Address(), authKeyPath, true); err != nil || exitCode != 0 { + t.Fatalf("Expected second --no-auth-key connection to succeed, exit=%d err=%v", exitCode, err) + } + assertDCatSuccessfulOutput(t, "authkey_noauth_2.tmp") + + waitForServerLogs() + if got := server.CountLogLinesContaining(authKeyFastPathLog); got != 0 { + t.Fatalf("Expected --no-auth-key to prevent fast-path registration, fast-path count=%d", got) + } +} + +func testPassphraseKeyAuthKeyRegistrationAndFastReconnect(t *testing.T) { + const passphrase = "secret-passphrase" + + authKeyPath := createPassphraseAuthKeyPair(t, "authkey-passphrase", passphrase) + server := startAuthKeyServer(t, "") + defer server.Stop() + + env := map[string]string{ + "DTAIL_KEY_PASSPHRASE": passphrase, + } + + exitCode, err := runDCatWithAuthKeyAndEnv(server.Context(), t, + "authkey_passphrase_1.tmp", server.Address(), authKeyPath, false, env) + if err != nil || exitCode != 0 { + t.Fatalf("Expected first passphrase-protected connection to succeed, exit=%d err=%v", exitCode, err) + } + assertDCatSuccessfulOutput(t, "authkey_passphrase_1.tmp") + waitForServerLogs() + if got := server.CountLogLinesContaining(authKeyFastPathLog); got != 0 { + t.Fatalf("Expected first passphrase-protected connection to use fallback, fast-path count=%d", got) + } + + exitCode, err = runDCatWithAuthKeyAndEnv(server.Context(), t, + "authkey_passphrase_2.tmp", server.Address(), authKeyPath, false, env) + if err != nil || exitCode != 0 { + t.Fatalf("Expected second passphrase-protected connection to succeed, exit=%d err=%v", exitCode, err) + } + assertDCatSuccessfulOutput(t, "authkey_passphrase_2.tmp") + fastPathCount := waitForLogCountAtLeast(server, authKeyFastPathLog, 1, 5*time.Second) + if fastPathCount < 1 { + t.Fatalf("Expected passphrase-protected key to use fast-path on reconnect, count=%d\nserver logs:\n%s", + fastPathCount, strings.Join(server.LogLines(), "\n")) + } +} + +type authKeyServer struct { + ctx context.Context + cancel context.CancelFunc + addr string + logs *authKeyServerLogs +} + +func (s *authKeyServer) Stop() { + s.cancel() +} + +func (s *authKeyServer) Context() context.Context { + return s.ctx +} + +func (s *authKeyServer) Address() string { + return s.addr +} + +func (s *authKeyServer) CountLogLinesContaining(substring string) int { + return s.logs.countContaining(substring) +} + +func (s *authKeyServer) LogLines() []string { + return s.logs.snapshot() +} + +type authKeyServerLogs struct { + mu sync.Mutex + lines []string +} + +func newAuthKeyServerLogs() *authKeyServerLogs { + return &authKeyServerLogs{ + lines: make([]string, 0, 128), + } +} + +func (l *authKeyServerLogs) append(line string) { + l.mu.Lock() + defer l.mu.Unlock() + l.lines = append(l.lines, line) +} + +func (l *authKeyServerLogs) countContaining(substring string) int { + l.mu.Lock() + defer l.mu.Unlock() + + count := 0 + for _, line := range l.lines { + if strings.Contains(line, substring) { + count++ + } + } + return count +} + +func (l *authKeyServerLogs) snapshot() []string { + l.mu.Lock() + defer l.mu.Unlock() + + lines := make([]string, len(l.lines)) + copy(lines, l.lines) + return lines +} + +func startAuthKeyServer(t *testing.T, cfgFile string) *authKeyServer { + t.Helper() + + ctx, cancel := context.WithCancel(context.Background()) + port := getUniquePortNumber() + args := []string{ + "--cfg", "none", + "--logger", "stdout", + "--logLevel", "info", + "--bindAddress", "localhost", + "--port", fmt.Sprintf("%d", port), + } + if cfgFile != "" { + args = append(args, "--cfg", cfgFile) + } + + stdoutCh, stderrCh, cmdErrCh, err := startCommandWithEnv(ctx, t, "", "../dserver", + map[string]string{"DTAIL_TURBOBOOST_DISABLE": "yes"}, args...) + if err != nil { + cancel() + t.Fatalf("Unable to start dserver: %v", err) + } + + logs := newAuthKeyServerLogs() + go func() { + for { + select { + case line, ok := <-stdoutCh: + if ok { + logs.append(line) + } + case line, ok := <-stderrCh: + if ok { + logs.append(line) + } + case err := <-cmdErrCh: + if err != nil { + logs.append(err.Error()) + } + return + case <-ctx.Done(): + return + } + } + }() + + if err := waitForServerReady(ctx, "localhost", port); err != nil { + cancel() + t.Fatalf("Unable to start dserver: %v", err) + } + return &authKeyServer{ + ctx: ctx, + cancel: cancel, + addr: fmt.Sprintf("localhost:%d", port), + logs: logs, + } +} + +func runDCatWithAuthKey(ctx context.Context, t *testing.T, outFile, + serverAddress, authKeyPath string, noAuthKey bool) (int, error) { + return runDCatWithAuthKeyAndEnv(ctx, t, outFile, serverAddress, authKeyPath, noAuthKey, nil) +} + +func runDCatWithAuthKeyAndEnv(ctx context.Context, t *testing.T, outFile, + serverAddress, authKeyPath string, noAuthKey bool, env map[string]string) (int, error) { + t.Helper() + + args := []string{ + "--plain", + "--cfg", "none", + "--servers", serverAddress, + "--files", "dcat1a.txt", + "--trustAllHosts", + "--noColor", + "--auth-key-path", authKeyPath, + } + if noAuthKey { + args = append(args, "--no-auth-key") + } + + return runCommandWithEnv(ctx, t, outFile, "../dcat", env, args...) +} + +func assertDCatSuccessfulOutput(t *testing.T, outFile string) { + t.Helper() + + outBytes, err := os.ReadFile(outFile) + if err != nil { + t.Fatalf("Unable to read dcat output file %s: %v", outFile, err) + } + + output := string(outBytes) + if strings.Contains(output, "SSH handshake failed") { + t.Fatalf("Expected successful SSH connection, got handshake failure in %s:\n%s", outFile, output) + } + if !strings.Contains(output, dcatExpectedFirstOutput) { + t.Fatalf("Expected dcat output to contain %q in %s, got:\n%s", dcatExpectedFirstOutput, outFile, output) + } +} + +func writeAuthKeyServerConfig(t *testing.T, ttlSeconds, maxPerUser int) string { + t.Helper() + + cfgPath := filepath.Join(t.TempDir(), "authkey_server_config.json") + cfgContent := fmt.Sprintf( + `{"Server":{"AuthKeyEnabled":true,"AuthKeyTTLSeconds":%d,"AuthKeyMaxPerUser":%d}}`, + ttlSeconds, maxPerUser, + ) + if err := os.WriteFile(cfgPath, []byte(cfgContent), 0600); err != nil { + t.Fatalf("Unable to write auth-key server config: %v", err) + } + return cfgPath +} + +func createAuthKeyPair(t *testing.T, keyName string) string { + t.Helper() + + keyPath := filepath.Join(t.TempDir(), keyName) + privateKey, err := rsa.GenerateKey(rand.Reader, 2048) + if err != nil { + t.Fatalf("Unable to generate private key: %v", err) + } + + privateKeyBytes := pem.EncodeToMemory(&pem.Block{ + Type: "RSA PRIVATE KEY", + Bytes: x509.MarshalPKCS1PrivateKey(privateKey), + }) + if err := os.WriteFile(keyPath, privateKeyBytes, 0600); err != nil { + t.Fatalf("Unable to write private key: %v", err) + } + + publicKey, err := gossh.NewPublicKey(&privateKey.PublicKey) + if err != nil { + t.Fatalf("Unable to generate public key: %v", err) + } + if err := os.WriteFile(keyPath+".pub", gossh.MarshalAuthorizedKey(publicKey), 0600); err != nil { + t.Fatalf("Unable to write public key: %v", err) + } + + return keyPath +} + +func createPassphraseAuthKeyPair(t *testing.T, keyName, passphrase string) string { + t.Helper() + + keyPath := filepath.Join(t.TempDir(), keyName) + privateKey, err := rsa.GenerateKey(rand.Reader, 2048) + if err != nil { + t.Fatalf("Unable to generate private key: %v", err) + } + + privateKeyBlock, err := gossh.MarshalPrivateKeyWithPassphrase(privateKey, "", []byte(passphrase)) + if err != nil { + t.Fatalf("Unable to marshal encrypted private key: %v", err) + } + if err := os.WriteFile(keyPath, pem.EncodeToMemory(privateKeyBlock), 0600); err != nil { + t.Fatalf("Unable to write encrypted private key: %v", err) + } + + publicKey, err := gossh.NewPublicKey(&privateKey.PublicKey) + if err != nil { + t.Fatalf("Unable to generate public key: %v", err) + } + if err := os.WriteFile(keyPath+".pub", gossh.MarshalAuthorizedKey(publicKey), 0600); err != nil { + t.Fatalf("Unable to write public key: %v", err) + } + + return keyPath +} + +func waitForServerLogs() { + time.Sleep(300 * time.Millisecond) +} + +func waitForLogCountAtLeast(server *authKeyServer, substring string, minCount int, timeout time.Duration) int { + if minCount <= 0 { + return server.CountLogLinesContaining(substring) + } + + deadline := time.Now().Add(timeout) + for { + count := server.CountLogLinesContaining(substring) + if count >= minCount { + return count + } + if time.Now().After(deadline) { + return count + } + time.Sleep(100 * time.Millisecond) + } +} diff --git a/integrationtests/commandutils.go b/integrationtests/commandutils.go index 8d81955..1947de4 100644 --- a/integrationtests/commandutils.go +++ b/integrationtests/commandutils.go @@ -2,6 +2,7 @@ package integrationtests import ( "bufio" + "bytes" "context" "fmt" "io" @@ -15,23 +16,38 @@ import ( func runCommand(ctx context.Context, t *testing.T, stdoutFile, cmdStr string, args ...string) (int, error) { + return runCommandWithEnv(ctx, t, stdoutFile, cmdStr, nil, args...) +} +func runCommandWithEnv(ctx context.Context, t *testing.T, stdoutFile, cmdStr string, + env map[string]string, args ...string) (int, error) { if _, err := os.Stat(cmdStr); err != nil { return 0, fmt.Errorf("no such executable '%s', please compile first: %w", cmdStr, err) } + // Log command execution if logger is available + if logger := GetTestLogger(ctx); logger != nil { + logger.LogCommand(cmdStr, args) + } + t.Log("Creating stdout file", stdoutFile) fd, err := os.Create(stdoutFile) if err != nil { - return 0, nil + return 0, err } defer fd.Close() t.Log("Running command", cmdStr, strings.Join(args, " ")) cmd := exec.CommandContext(ctx, cmdStr, args...) + cmd.Env = os.Environ() + for key, value := range env { + cmd.Env = append(cmd.Env, fmt.Sprintf("%s=%s", key, value)) + } out, err := cmd.CombinedOutput() t.Log("Done running command!", err) - _, _ = fd.Write(out) + if _, copyErr := io.Copy(fd, bytes.NewReader(out)); copyErr != nil { + return exitCodeFromError(err), copyErr + } return exitCodeFromError(err), err } @@ -48,8 +64,54 @@ func runCommandRetry(ctx context.Context, t *testing.T, retries int, stdoutFile, return } +func runCommandUntilValid(ctx context.Context, t *testing.T, attempts int, delay time.Duration, + stdoutFile, cmd string, validate func() error, args ...string) error { + + t.Helper() + + if attempts < 1 { + attempts = 1 + } + + var lastErr error + for i := 0; i < attempts; i++ { + exitCode, err := runCommand(ctx, t, stdoutFile, cmd, args...) + if err == nil { + validateErr := validate() + if validateErr == nil { + return nil + } + lastErr = validateErr + } else { + lastErr = fmt.Errorf("command %s failed with exit code %d: %w", cmd, exitCode, err) + } + + if i == attempts-1 { + break + } + + timer := time.NewTimer(delay) + select { + case <-ctx.Done(): + timer.Stop() + if lastErr != nil { + return lastErr + } + return ctx.Err() + case <-timer.C: + } + } + + return lastErr +} + func startCommand(ctx context.Context, t *testing.T, inPipeFile, cmdStr string, args ...string) (<-chan string, <-chan string, <-chan error, error) { + return startCommandWithEnv(ctx, t, inPipeFile, cmdStr, nil, args...) +} + +func startCommandWithEnv(ctx context.Context, t *testing.T, inPipeFile, + cmdStr string, env map[string]string, args ...string) (<-chan string, <-chan string, <-chan error, error) { stdoutCh := make(chan string) stderrCh := make(chan string) @@ -59,9 +121,23 @@ func startCommand(ctx context.Context, t *testing.T, inPipeFile, fmt.Errorf("no such executable '%s', please compile first: %w", cmdStr, err) } + // Log command execution if logger is available + if logger := GetTestLogger(ctx); logger != nil { + logger.LogCommand(cmdStr, args) + } + t.Log(cmdStr, strings.Join(args, " ")) cmd := exec.CommandContext(ctx, cmdStr, args...) + // Always inherit environment variables + cmd.Env = os.Environ() + // Add any additional environment variables if provided + if env != nil { + for k, v := range env { + cmd.Env = append(cmd.Env, fmt.Sprintf("%s=%s", k, v)) + } + } + var stdinPipe io.WriteCloser if inPipeFile != "" { var err error diff --git a/integrationtests/dcat1d.txt b/integrationtests/dcat1d.txt deleted file mode 100644 index 074c277..0000000 --- a/integrationtests/dcat1d.txt +++ /dev/null @@ -1 +0,0 @@ -single line without newline \ No newline at end of file diff --git a/integrationtests/dcat_logpayload_test.go b/integrationtests/dcat_logpayload_test.go new file mode 100644 index 0000000..823e33f --- /dev/null +++ b/integrationtests/dcat_logpayload_test.go @@ -0,0 +1,141 @@ +package integrationtests + +import ( + "context" + "os" + "path/filepath" + "strings" + "testing" + + "github.com/mimecast/dtail/internal/config" +) + +// payloadMarker is the last line of dcat1a.txt. It is distinctive enough that +// its presence in a file proves the retrieved payload was written there. +const payloadMarker = "500 Sat 2 Oct 13:46:46 EEST 2021" + +// readDailyLog concatenates every YYYYMMDD.log file the fout logger may have +// written into dir. A missing/empty dir returns "" (the default logger only +// creates the file on the first write, so a payload-free run may leave none). +func readDailyLog(t *testing.T, dir string) string { + t.Helper() + matches, err := filepath.Glob(filepath.Join(dir, "*.log")) + if err != nil { + t.Fatalf("globbing log dir %s: %v", dir, err) + } + var sb strings.Builder + for _, m := range matches { + content, err := os.ReadFile(m) + if err != nil { + t.Fatalf("reading log file %s: %v", m, err) + } + sb.Write(content) + } + return sb.String() +} + +// TestDCatLogPayload verifies Option B of task dt0: the default client log file +// (the fout logger's daily file) records diagnostics only, and payload teeing +// is opt-in via --log-payload. All sub-tests run serverless so the client log +// output is deterministic (no network timing in diagnostics). +func TestDCatLogPayload(t *testing.T) { + if !config.Env("DTAIL_INTEGRATION_TEST_RUN_MODE") { + t.Log("Skipping") + return + } + + cleanupTmpFiles(t) + testLogger := NewTestLogger("TestDCatLogPayload") + defer testLogger.WriteLogFile() + + inFile := "dcat1a.txt" + + // Default: file must be diagnostics-only, no payload; payload still on stdout. + t.Run("DefaultDiagnosticsOnlyNoPayload", func(t *testing.T) { + logDir := t.TempDir() + outFile := "dcatlogpayload_default.tmp" + ctx := WithTestLogger(context.Background(), testLogger) + + if _, err := runCommand(ctx, t, outFile, "../dcat", + "--logger", "fout", "--logDir", logDir, "--logLevel", "debug", + "--noColor", "--cfg", "none", inFile); err != nil { + t.Fatal(err) + } + + logContent := readDailyLog(t, logDir) + if strings.Contains(logContent, payloadMarker) { + t.Fatalf("payload leaked into the daily client log file by default (found %q)", payloadMarker) + } + // Diagnostics must still land in the file: in integration mode every + // client diagnostic line carries the "integrationtest" hostname token. + if !strings.Contains(logContent, "integrationtest") { + t.Fatalf("expected diagnostics in the daily log file, got none:\n%s", logContent) + } + // Payload must still reach the terminal/stdout. + stdout := readTmpFile(t, outFile) + if !strings.Contains(stdout, payloadMarker) { + t.Fatal("payload missing from stdout; it must always reach the terminal") + } + }) + + // Opt-in: --log-payload restores the legacy full tee into the file. + t.Run("OptInTeesPayloadToFile", func(t *testing.T) { + logDir := t.TempDir() + outFile := "dcatlogpayload_optin.tmp" + ctx := WithTestLogger(context.Background(), testLogger) + + if _, err := runCommand(ctx, t, outFile, "../dcat", + "--logger", "fout", "--logDir", logDir, "--logLevel", "debug", + "--noColor", "--log-payload", "--cfg", "none", inFile); err != nil { + t.Fatal(err) + } + + logContent := readDailyLog(t, logDir) + if !strings.Contains(logContent, payloadMarker) { + t.Fatalf("expected payload teed into the daily log file with --log-payload, not found") + } + }) + + // Stdout must be byte-identical with and without --log-payload: only the + // FILE content changes, never what the user sees on the terminal. + t.Run("StdoutByteIdenticalWithAndWithoutFlag", func(t *testing.T) { + defaultLogDir := t.TempDir() + optinLogDir := t.TempDir() + defaultOut := "dcatlogpayload_stdout_default.tmp" + optinOut := "dcatlogpayload_stdout_optin.tmp" + ctx := WithTestLogger(context.Background(), testLogger) + + if _, err := runCommand(ctx, t, defaultOut, "../dcat", + "--plain", "--logger", "fout", "--logDir", defaultLogDir, + "--cfg", "none", inFile); err != nil { + t.Fatal(err) + } + if _, err := runCommand(ctx, t, optinOut, "../dcat", + "--plain", "--logger", "fout", "--logDir", optinLogDir, + "--log-payload", "--cfg", "none", inFile); err != nil { + t.Fatal(err) + } + + if got, want := readTmpFile(t, optinOut), readTmpFile(t, defaultOut); got != want { + t.Fatalf("stdout differs between default and --log-payload runs:\n got %q\nwant %q", got, want) + } + + // Sanity: file behavior still toggled underneath the identical stdout. + if strings.Contains(readDailyLog(t, defaultLogDir), payloadMarker) { + t.Fatal("default run leaked payload into the log file") + } + if !strings.Contains(readDailyLog(t, optinLogDir), payloadMarker) { + t.Fatal("--log-payload run did not tee payload into the log file") + } + }) +} + +// readTmpFile reads a captured stdout file produced by runCommand. +func readTmpFile(t *testing.T, name string) string { + t.Helper() + content, err := os.ReadFile(name) + if err != nil { + t.Fatalf("reading %s: %v", name, err) + } + return string(content) +} diff --git a/integrationtests/dcat_test.go b/integrationtests/dcat_test.go index b2a041c..4a34c76 100644 --- a/integrationtests/dcat_test.go +++ b/integrationtests/dcat_test.go @@ -2,8 +2,11 @@ package integrationtests import ( "context" + "fmt" "os" + "strings" "testing" + "time" "github.com/mimecast/dtail/internal/config" ) @@ -14,38 +17,238 @@ func TestDCat1(t *testing.T) { return } - inFiles := []string{"dcat1a.txt", "dcat1b.txt", "dcat1c.txt", "dcat1d.txt"} - for _, inFile := range inFiles { - if err := testDCat1(t, inFile); err != nil { - t.Error(err) - return + cleanupTmpFiles(t) + testLogger := NewTestLogger("TestDCat1") + defer testLogger.WriteLogFile() + + // Test in serverless mode + t.Run("Serverless", func(t *testing.T) { + inFiles := []string{"dcat1a.txt", "dcat1b.txt", "dcat1c.txt"} + for _, inFile := range inFiles { + if err := testDCat1Serverless(t, testLogger, inFile); err != nil { + t.Error(err) + return + } } - } + }) + + // Test in server mode + t.Run("ServerMode", func(t *testing.T) { + inFiles := []string{"dcat1a.txt", "dcat1b.txt", "dcat1c.txt"} + for _, inFile := range inFiles { + if err := testDCat1WithServer(t, testLogger, inFile); err != nil { + t.Error(err) + return + } + } + }) } -func testDCat1(t *testing.T, inFile string) error { - outFile := "dcat1.out" +func testDCat1Serverless(t *testing.T, logger *TestLogger, inFile string) error { + outFile := "dcat1.tmp" + ctx := WithTestLogger(context.Background(), logger) - _, err := runCommand(context.TODO(), t, outFile, + _, err := runCommand(ctx, t, outFile, "../dcat", "--plain", "--cfg", "none", inFile) if err != nil { return err } - if err := compareFiles(t, outFile, inFile); err != nil { + if err := compareFilesWithContext(ctx, t, outFile, inFile); err != nil { return err } - os.Remove(outFile) return nil } +func testDCat1WithServer(t *testing.T, logger *TestLogger, inFile string) error { + outFile := "dcat1.tmp" + port := getUniquePortNumber() + bindAddress := "localhost" + + ctx, cancel := context.WithCancel(context.Background()) + ctx = WithTestLogger(ctx, logger) + defer cancel() + + // Start dserver + _, _, _, err := startCommand(ctx, t, + "", "../dserver", + "--cfg", "none", + "--logger", "stdout", + "--logLevel", "error", + "--bindAddress", bindAddress, + "--port", fmt.Sprintf("%d", port), + ) + if err != nil { + return err + } + + if err := waitForServerReady(ctx, bindAddress, port); err != nil { + t.Error(err) + return err + } + + // Run dcat against the server and wait for the full file to be available. + err = runCommandUntilValid(ctx, t, 5, 200*time.Millisecond, outFile, "../dcat", func() error { + return compareFilesWithContext(ctx, t, outFile, inFile) + }, + "--plain", "--cfg", "none", + "--servers", fmt.Sprintf("%s:%d", bindAddress, port), + "--files", inFile, + "--trustAllHosts", + "--noColor") + + cancel() + return err +} + +func TestDCat1Colors(t *testing.T) { + if !config.Env("DTAIL_INTEGRATION_TEST_RUN_MODE") { + t.Log("Skipping") + return + } + + cleanupTmpFiles(t) + testLogger := NewTestLogger("TestDCat1Colors") + defer testLogger.WriteLogFile() + + // Test in serverless mode + t.Run("Serverless", func(t *testing.T) { + testDCat1ColorsServerless(t, testLogger) + }) + + // Test in server mode + t.Run("ServerMode", func(t *testing.T) { + testDCat1ColorsWithServer(t, testLogger) + }) +} + +func testDCat1ColorsServerless(t *testing.T, logger *TestLogger) { + inFile := "dcat1a.txt" + outFile := "dcat1colors_serverless.tmp" + ctx := WithTestLogger(context.Background(), logger) + + // Run without --plain to get colored output + _, err := runCommand(ctx, t, outFile, + "../dcat", "--cfg", "none", inFile) + if err != nil { + t.Error(err) + return + } + + // Just verify it ran successfully and produced output + info, err := os.Stat(outFile) + if err != nil { + t.Error("Output file not created:", err) + return + } + if info.Size() == 0 { + t.Error("Output file is empty") + return + } + + // Verify output contains ANSI color codes + content, err := os.ReadFile(outFile) + if err != nil { + t.Error("Failed to read output file:", err) + return + } + if !strings.Contains(string(content), "\033[") { + t.Error("Output does not contain ANSI color codes") + return + } + + // Log verification + logger.LogFileComparison(outFile, "ANSI color codes", "contains check") +} + +func testDCat1ColorsWithServer(t *testing.T, logger *TestLogger) { + inFile := "dcat1a.txt" + outFile := "dcat1colors_server.tmp" + port := getUniquePortNumber() + bindAddress := "localhost" + + ctx, cancel := context.WithCancel(context.Background()) + ctx = WithTestLogger(ctx, logger) + defer cancel() + + // Start dserver + _, _, _, err := startCommand(ctx, t, + "", "../dserver", + "--cfg", "none", + "--logger", "stdout", + "--logLevel", "error", + "--bindAddress", bindAddress, + "--port", fmt.Sprintf("%d", port), + ) + if err != nil { + t.Error(err) + return + } + + if err := waitForServerReady(ctx, bindAddress, port); err != nil { + t.Error(err) + return + } + + err = runCommandUntilValid(ctx, t, 5, 200*time.Millisecond, outFile, "../dcat", func() error { + info, statErr := os.Stat(outFile) + if statErr != nil { + return fmt.Errorf("output file not created: %w", statErr) + } + if info.Size() == 0 { + return fmt.Errorf("output file is empty") + } + + content, readErr := os.ReadFile(outFile) + if readErr != nil { + return fmt.Errorf("failed to read output file: %w", readErr) + } + if !strings.Contains(string(content), "REMOTE") && !strings.Contains(string(content), "SERVER") { + preview := string(content) + if len(preview) > 500 { + preview = preview[:500] + } + return fmt.Errorf("server mode output does not contain server metadata. First 500 chars:\n%s", preview) + } + return nil + }, + "--cfg", "none", + "--servers", fmt.Sprintf("%s:%d", bindAddress, port), + "--files", inFile, + "--trustAllHosts") + cancel() + if err != nil { + t.Error(err) + return + } + logger.LogFileComparison(outFile, "server metadata (REMOTE/SERVER)", "contains check") +} + func TestDCat2(t *testing.T) { if !config.Env("DTAIL_INTEGRATION_TEST_RUN_MODE") { return } + + cleanupTmpFiles(t) + testLogger := NewTestLogger("TestDCat2") + defer testLogger.WriteLogFile() + + // Test in serverless mode + t.Run("Serverless", func(t *testing.T) { + testDCat2Serverless(t, testLogger) + }) + + // Test in server mode + t.Run("ServerMode", func(t *testing.T) { + testDCat2WithServer(t, testLogger) + }) +} + +func testDCat2Serverless(t *testing.T, logger *TestLogger) { inFile := "dcat2.txt" expectedFile := "dcat2.txt.expected" - outFile := "dcat2.out" + outFile := "dcat2_serverless.tmp" + ctx := WithTestLogger(context.Background(), logger) args := []string{"--plain", "--logLevel", "error", "--cfg", "none"} @@ -54,44 +257,163 @@ func TestDCat2(t *testing.T) { args = append(args, inFile) } - _, err := runCommand(context.TODO(), t, outFile, "../dcat", args...) + _, err := runCommand(ctx, t, outFile, "../dcat", args...) + if err != nil { + t.Error(err) + return + } + + if err := compareFilesContentsWithContext(ctx, t, outFile, expectedFile); err != nil { + t.Error(err) + return + } +} + +func testDCat2WithServer(t *testing.T, logger *TestLogger) { + inFile := "dcat2.txt" + expectedFile := "dcat2.txt.expected" + outFile := "dcat2_server.tmp" + port := getUniquePortNumber() + bindAddress := "localhost" + + ctx, cancel := context.WithCancel(context.Background()) + ctx = WithTestLogger(ctx, logger) + defer cancel() + + // This is a correctness test (server output must equal the expected file), + // not a turbo-vs-non-turbo comparison. Under DTAIL_INTEGRATION_TEST_RUN_MODE + // the server force-disables turbo boost (see internal/config/initializer.go), + // so the dserver started here always runs on the non-turbo path regardless of + // any DTAIL_TURBOBOOST_* env var. Genuine turbo coverage lives in the + // benchmark harness (benchmarks/) which runs outside integration-test mode. + // Use higher concurrency for faster test execution. + _, _, _, err := startCommandWithEnv(ctx, t, + "", "../dserver", + nil, + "--cfg", "test_server_complete.json", + "--logger", "stdout", + "--logLevel", "error", + "--bindAddress", bindAddress, + "--port", fmt.Sprintf("%d", port), + ) if err != nil { t.Error(err) return } - if err := compareFilesContents(t, outFile, expectedFile); err != nil { + if err := waitForServerReady(ctx, bindAddress, port); err != nil { t.Error(err) return } - os.Remove(outFile) + // Cat file 100 times in one session. + var files []string + for i := 0; i < 100; i++ { + files = append(files, inFile) + } + + args := []string{"--plain", "--logLevel", "error", "--cfg", "none", + "--servers", fmt.Sprintf("%s:%d", bindAddress, port), + "--trustAllHosts", "--noColor", "--files", strings.Join(files, ",")} + + err = runCommandUntilValid(ctx, t, 5, 200*time.Millisecond, outFile, "../dcat", func() error { + return compareFilesContentsWithContext(ctx, t, outFile, expectedFile) + }, args...) + cancel() + if err != nil { + t.Error(err) + return + } } func TestDCat3(t *testing.T) { if !config.Env("DTAIL_INTEGRATION_TEST_RUN_MODE") { return } + + cleanupTmpFiles(t) + testLogger := NewTestLogger("TestDCat3") + defer testLogger.WriteLogFile() + + // Test in serverless mode + t.Run("Serverless", func(t *testing.T) { + testDCat3Serverless(t, testLogger) + }) + + // Test in server mode + t.Run("ServerMode", func(t *testing.T) { + testDCat3WithServer(t, testLogger) + }) +} + +func testDCat3Serverless(t *testing.T, logger *TestLogger) { inFile := "dcat3.txt" expectedFile := "dcat3.txt.expected" - outFile := "dcat3.out" + outFile := "dcat3_serverless.tmp" + ctx := WithTestLogger(context.Background(), logger) args := []string{"--plain", "--logLevel", "error", "--cfg", "none", inFile} // Notice, with DTAIL_INTEGRATION_TEST_RUN_MODE the DTail max line length is set // to 1024! - _, err := runCommand(context.TODO(), t, outFile, "../dcat", args...) + _, err := runCommand(ctx, t, outFile, "../dcat", args...) if err != nil { t.Error(err) return } - if err := compareFilesContents(t, outFile, expectedFile); err != nil { + if err := compareFilesContentsWithContext(ctx, t, outFile, expectedFile); err != nil { t.Error(err) return } +} - os.Remove(outFile) +func testDCat3WithServer(t *testing.T, logger *TestLogger) { + inFile := "dcat3.txt" + expectedFile := "dcat3.txt.expected" + outFile := "dcat3_server.tmp" + port := getUniquePortNumber() + bindAddress := "localhost" + + ctx, cancel := context.WithCancel(context.Background()) + ctx = WithTestLogger(ctx, logger) + defer cancel() + + // Start dserver + _, _, _, err := startCommand(ctx, t, + "", "../dserver", + "--cfg", "none", + "--logger", "stdout", + "--logLevel", "error", + "--bindAddress", bindAddress, + "--port", fmt.Sprintf("%d", port), + ) + if err != nil { + t.Error(err) + return + } + + if err := waitForServerReady(ctx, bindAddress, port); err != nil { + t.Error(err) + return + } + + args := []string{"--plain", "--logLevel", "error", "--cfg", "none", + "--servers", fmt.Sprintf("%s:%d", bindAddress, port), + "--files", inFile, + "--trustAllHosts", + "--noColor"} + + // Notice, with DTAIL_INTEGRATION_TEST_RUN_MODE the DTail max line length is set + // to 1024! + err = runCommandUntilValid(ctx, t, 5, 200*time.Millisecond, outFile, "../dcat", func() error { + return compareFilesContentsWithContext(ctx, t, outFile, expectedFile) + }, args...) + cancel() + if err != nil { + t.Error(err) + return + } } func TestDCatColors(t *testing.T) { @@ -99,11 +421,28 @@ func TestDCatColors(t *testing.T) { return } + cleanupTmpFiles(t) + testLogger := NewTestLogger("TestDCatColors") + defer testLogger.WriteLogFile() + + // Test in serverless mode + t.Run("Serverless", func(t *testing.T) { + testDCatColorsServerless(t, testLogger) + }) + + // Test in server mode + t.Run("ServerMode", func(t *testing.T) { + testDCatColorsWithServer(t, testLogger) + }) +} + +func testDCatColorsServerless(t *testing.T, logger *TestLogger) { inFile := "dcatcolors.txt" - outFile := "dcatcolors.out" + outFile := "dcatcolors_serverless.tmp" expectedFile := "dcatcolors.expected" + ctx := WithTestLogger(context.Background(), logger) - _, err := runCommand(context.TODO(), t, outFile, + _, err := runCommand(ctx, t, outFile, "../dcat", "--logLevel", "error", "--cfg", "none", inFile) if err != nil { @@ -111,10 +450,53 @@ func TestDCatColors(t *testing.T) { return } - if err := compareFiles(t, outFile, expectedFile); err != nil { + if err := compareFilesWithContext(ctx, t, outFile, expectedFile); err != nil { + t.Error(err) + return + } +} + +func testDCatColorsWithServer(t *testing.T, logger *TestLogger) { + inFile := "dcatcolors.txt" + outFile := "dcatcolors_server.tmp" + expectedFile := "dcatcolors.server.expected" + port := getUniquePortNumber() + bindAddress := "localhost" + + ctx, cancel := context.WithCancel(context.Background()) + ctx = WithTestLogger(ctx, logger) + defer cancel() + + // Start dserver + _, _, _, err := startCommand(ctx, t, + "", "../dserver", + "--cfg", "none", + "--logger", "stdout", + "--logLevel", "error", + "--bindAddress", bindAddress, + "--port", fmt.Sprintf("%d", port), + ) + if err != nil { t.Error(err) return } - os.Remove(outFile) + if err := waitForServerReady(ctx, bindAddress, port); err != nil { + t.Error(err) + return + } + + err = runCommandUntilValid(ctx, t, 5, 200*time.Millisecond, outFile, "../dcat", func() error { + return compareFilesWithContext(ctx, t, outFile, expectedFile) + }, + "--logLevel", "error", "--cfg", "none", + "--servers", fmt.Sprintf("%s:%d", bindAddress, port), + "--files", inFile, + "--trustAllHosts", + "--noColor") + cancel() + if err != nil { + t.Error(err) + return + } } diff --git a/integrationtests/dcatcolors.expected b/integrationtests/dcatcolors.expected index 859b17b..4f27e64 100644 --- a/integrationtests/dcatcolors.expected +++ b/integrationtests/dcatcolors.expected @@ -1,2755 +1,2754 @@ REMOTE|integrationtest|100|1|dcatcolors.txt|FATAL|20211015-053919|SSH relaxed-auth mode enabled -REMOTE|integrationtest|100|2|dcatcolors.txt|INFO|20211015-053919|Creating server|DTail 4.0.0-RC1 Protocol 4 Have a lot of fun! -REMOTE|integrationtest|100|3|dcatcolors.txt|INFO|20211015-053919|Generating private server RSA host key -REMOTE|integrationtest|100|4|dcatcolors.txt|ERROR|20211015-053919|Unable to write private server RSA host key to file|cache/ssh_host_key|open cache/ssh_host_key: no such file or directory -REMOTE|integrationtest|100|5|dcatcolors.txt|INFO|20211015-053919|Starting server -REMOTE|integrationtest|100|6|dcatcolors.txt|INFO|20211015-053919|Binding server|0.0.0.0:2222 -REMOTE|integrationtest|100|7|dcatcolors.txt|DEBUG|20211015-053919|Starting listener loop -REMOTE|integrationtest|100|8|dcatcolors.txt|INFO|20211015-053919|Starting continuous job runner after 10s -REMOTE|integrationtest|100|9|dcatcolors.txt|INFO|20211015-053919|Starting scheduled job runner after 10s -REMOTE|integrationtest|100|10|dcatcolors.txt|INFO|20211015-053926|Handling connection -REMOTE|integrationtest|100|11|dcatcolors.txt|INFO|20211015-053928|paul@172.17.0.1:33710|Incoming authorization -REMOTE|integrationtest|100|12|dcatcolors.txt|FATAL|20211015-053928|paul@172.17.0.1:33710|Granting permissions via relaxed-auth -REMOTE|integrationtest|100|13|dcatcolors.txt|INFO|20211015-053928|1|stats.go:53|8|16|7|1.34|781h28m6s|MAPREDUCE:STATS|currentConnections=1|lifetimeConnections=1 -REMOTE|integrationtest|100|14|dcatcolors.txt|INFO|20211015-053928|paul@172.17.0.1:33710|Invoking channel handler -REMOTE|integrationtest|100|15|dcatcolors.txt|INFO|20211015-053928|paul@172.17.0.1:33710|Invoking request handler -REMOTE|integrationtest|100|16|dcatcolors.txt|DEBUG|20211015-053928|paul@172.17.0.1:33710|Creating new server handler -REMOTE|integrationtest|100|17|dcatcolors.txt|DEBUG|20211015-053928|paul@172.17.0.1:33710|protocol 4 base64 dGFpbDogL3Zhci9sb2cvZHNlcnZlci8qIHJlZ2V4Om5vb3Ag -REMOTE|integrationtest|100|18|dcatcolors.txt|TRACE|20211015-053928|paul@172.17.0.1:33710|Base64 decoded received command|tail: /var/log/dserver/* regex:noop |36|[tail: /var/log/dserver/* regex:noop ]|at /home/paul/git/dtail/internal/server/handlers/basehandler.go:225 -REMOTE|integrationtest|100|19|dcatcolors.txt|DEBUG|20211015-053928|paul@172.17.0.1:33710|Handling user command|36|[tail: /var/log/dserver/* regex:noop ] -REMOTE|integrationtest|100|20|dcatcolors.txt|DEBUG|20211015-053928|paul@172.17.0.1:33710|/var/log/dserver/dserver.log|readfiles|Checking config permissions -REMOTE|integrationtest|100|21|dcatcolors.txt|FATAL|20211015-053928|paul@172.17.0.1:33710|/var/log/dserver/dserver.log|readfiles|Server releaxed auth enabled -REMOTE|integrationtest|100|22|dcatcolors.txt|INFO|20211015-053928|paul@172.17.0.1:33710|Start reading file|/var/log/dserver/dserver.log|dserver.log -REMOTE|integrationtest|100|23|dcatcolors.txt|DEBUG|20211015-053928|readFile|readFile(filePath:/var/log/dserver/dserver.log,globID:dserver.log,retry:true,canSkipLines:true,seekEOF:true) -REMOTE|integrationtest|100|24|dcatcolors.txt|INFO|20211015-053929|1|stats.go:53|8|26|7|1.34|781h28m7s|MAPREDUCE:STATS|currentConnections=1|lifetimeConnections=1 -REMOTE|integrationtest|100|25|dcatcolors.txt|DEBUG|20211015-053931|/var/log/dserver/dserver.log|File truncation check -REMOTE|integrationtest|100|26|dcatcolors.txt|DEBUG|20211015-053934|/var/log/dserver/dserver.log|File truncation check -REMOTE|integrationtest|100|27|dcatcolors.txt|DEBUG|20211015-053937|/var/log/dserver/dserver.log|File truncation check -REMOTE|integrationtest|100|28|dcatcolors.txt|INFO|20211015-053939|1|stats.go:53|8|16|7|1.21|781h28m16s|MAPREDUCE:STATS|lifetimeConnections=1|currentConnections=0 -REMOTE|integrationtest|100|29|dcatcolors.txt|INFO|20211015-053939|paul@172.17.0.1:33710|Good bye Mister! -REMOTE|integrationtest|100|30|dcatcolors.txt|DEBUG|20211015-053939|paul@172.17.0.1:33710|shutdown() -REMOTE|integrationtest|100|31|dcatcolors.txt|TRACE|20211015-053939|paul@172.17.0.1:33710|flush()|at /home/paul/git/dtail/internal/server/handlers/basehandler.go:278 -REMOTE|integrationtest|100|32|dcatcolors.txt|DEBUG|20211015-053939|paul@172.17.0.1:33710|ALL lines sent|0xc0002aa000 -REMOTE|integrationtest|100|33|dcatcolors.txt|INFO|20211015-053939|1|stats.go:53|8|11|7|1.21|781h28m17s|MAPREDUCE:STATS|currentConnections=0|lifetimeConnections=1 -REMOTE|integrationtest|100|34|dcatcolors.txt|INFO|20211015-053942|Handling connection -REMOTE|integrationtest|100|35|dcatcolors.txt|INFO|20211015-053942|paul@172.17.0.1:33712|Incoming authorization -REMOTE|integrationtest|100|36|dcatcolors.txt|FATAL|20211015-053942|paul@172.17.0.1:33712|Granting permissions via relaxed-auth -REMOTE|integrationtest|100|37|dcatcolors.txt|INFO|20211015-053942|1|stats.go:53|8|15|7|1.11|781h28m19s|MAPREDUCE:STATS|lifetimeConnections=2|currentConnections=1 -REMOTE|integrationtest|100|38|dcatcolors.txt|INFO|20211015-053942|paul@172.17.0.1:33712|Invoking channel handler -REMOTE|integrationtest|100|39|dcatcolors.txt|INFO|20211015-053942|paul@172.17.0.1:33712|Invoking request handler -REMOTE|integrationtest|100|40|dcatcolors.txt|DEBUG|20211015-053942|paul@172.17.0.1:33712|Creating new server handler -REMOTE|integrationtest|100|41|dcatcolors.txt|DEBUG|20211015-053942|paul@172.17.0.1:33712|protocol 4 base64 Y2F0OiAvZXRjL3Bhc3N3ZCByZWdleDpub29wIA== -REMOTE|integrationtest|100|42|dcatcolors.txt|TRACE|20211015-053942|paul@172.17.0.1:33712|Base64 decoded received command|cat: /etc/passwd regex:noop |28|[cat: /etc/passwd regex:noop ]|at /home/paul/git/dtail/internal/server/handlers/basehandler.go:225 -REMOTE|integrationtest|100|43|dcatcolors.txt|DEBUG|20211015-053942|paul@172.17.0.1:33712|Handling user command|28|[cat: /etc/passwd regex:noop ] -REMOTE|integrationtest|100|44|dcatcolors.txt|DEBUG|20211015-053942|paul@172.17.0.1:33712|/etc/passwd|readfiles|Checking config permissions -REMOTE|integrationtest|100|45|dcatcolors.txt|FATAL|20211015-053942|paul@172.17.0.1:33712|/etc/passwd|readfiles|Server releaxed auth enabled -REMOTE|integrationtest|100|46|dcatcolors.txt|