From b9f55ab50842c9e90e03bcb66a33bf7871f0f8d5 Mon Sep 17 00:00:00 2001 From: jamesread Date: Fri, 23 Jan 2026 14:18:30 +0000 Subject: [PATCH] fix: load logs on startup (#299) --- .../tests/logPersistence/config.yaml | 16 ++ .../tests/logPersistence/logPersistence.mjs | 258 ++++++++++++++++++ service/internal/executor/loadlogs.go | 216 +++++++++++++++ service/main.go | 2 + 4 files changed, 492 insertions(+) create mode 100644 integration-tests/tests/logPersistence/config.yaml create mode 100644 integration-tests/tests/logPersistence/logPersistence.mjs create mode 100644 service/internal/executor/loadlogs.go diff --git a/integration-tests/tests/logPersistence/config.yaml b/integration-tests/tests/logPersistence/config.yaml new file mode 100644 index 0000000..8871205 --- /dev/null +++ b/integration-tests/tests/logPersistence/config.yaml @@ -0,0 +1,16 @@ +# +# Integration Test Config: Log Persistence +# + +listenAddressSingleHTTPFrontend: 0.0.0.0:1337 + +logLevel: "DEBUG" +checkForUpdates: false + +saveLogs: + resultsDirectory: /tmp/olivetin-test-logs + +actions: +- title: Echo Test + shell: echo "Hello from persisted log test" + icon: test diff --git a/integration-tests/tests/logPersistence/logPersistence.mjs b/integration-tests/tests/logPersistence/logPersistence.mjs new file mode 100644 index 0000000..f7d93bd --- /dev/null +++ b/integration-tests/tests/logPersistence/logPersistence.mjs @@ -0,0 +1,258 @@ +import { describe, it, before, after } from 'mocha' +import { expect } from 'chai' +import { By, Condition } from 'selenium-webdriver' +import fs from 'fs' +import path from 'path' +import { + getRootAndWait, + getActionButtons, + takeScreenshotOnFailure, +} from '../../lib/elements.js' + +describe('config: logPersistence', function () { + const logsDir = '/tmp/olivetin-test-logs' + let firstExecutionTrackingId = null + + before(async function () { + // Clean up any existing test logs + if (fs.existsSync(logsDir)) { + fs.rmSync(logsDir, { recursive: true, force: true }) + } + fs.mkdirSync(logsDir, { recursive: true }) + + await runner.start('logPersistence') + }) + + after(async () => { + await runner.stop() + + // Clean up test logs directory + if (fs.existsSync(logsDir)) { + fs.rmSync(logsDir, { recursive: true, force: true }) + } + }) + + afterEach(function () { + takeScreenshotOnFailure(this.currentTest, webdriver) + }) + + it('Execute action and verify log is saved to disk', async function () { + this.timeout(30000) + await getRootAndWait() + + // Get initial log file count + const initialLogCount = fs.existsSync(logsDir) + ? fs.readdirSync(logsDir).filter(f => f.endsWith('.yaml')).length + : 0 + + // Wait for action button to be available + await webdriver.wait( + new Condition('wait for Echo Test button', async () => { + const buttons = await webdriver.findElements(By.css('.action-button button')) + for (const btn of buttons) { + const text = await btn.getText() + if (text.includes('Echo Test')) { + return true + } + } + return false + }), + 10000 + ) + + // Find and click the Echo Test button + const buttons = await webdriver.findElements(By.css('.action-button button')) + let echoButton = null + for (const btn of buttons) { + const text = await btn.getText() + if (text.includes('Echo Test')) { + echoButton = btn + break + } + } + expect(echoButton).to.not.be.null + + // Click the button to execute the action + await echoButton.click() + + // Wait for the log file to be written to disk + await webdriver.wait( + new Condition('wait for log file to appear', async () => { + if (!fs.existsSync(logsDir)) { + return false + } + const logFiles = fs.readdirSync(logsDir).filter(f => f.endsWith('.yaml')) + return logFiles.length > initialLogCount + }), + 10000 + ) + + // Wait a bit more to ensure file is fully written + await webdriver.sleep(1000) + + // Get the newest log file + const logFiles = fs.readdirSync(logsDir).filter(f => f.endsWith('.yaml')) + expect(logFiles.length).to.be.greaterThan(initialLogCount, 'At least one new log file should be saved') + + // Sort by modification time to get the newest + const logFilesWithStats = logFiles.map(f => { + const filePath = path.join(logsDir, f) + return { + name: f, + path: filePath, + mtime: fs.statSync(filePath).mtime + } + }).sort((a, b) => b.mtime - a.mtime) + + const newestLogFile = logFilesWithStats[0] + expect(newestLogFile).to.not.be.undefined + + // Read the log file to extract the tracking ID + const logFileContent = fs.readFileSync(newestLogFile.path, 'utf8') + + // Verify the log file contains expected content (action title might be in different fields) + expect(logFileContent.length).to.be.greaterThan(0, 'Log file should not be empty') + + // Extract tracking ID from filename first (most reliable) + // Filename format: .<timestamp>.<trackingId>.yaml + // Tracking IDs are UUIDs, so match UUID pattern at the end before .yaml + let uuidMatch = newestLogFile.name.match(/([a-f0-9]{8}-[a-f0-9]{4}-[a-f0-9]{4}-[a-f0-9]{4}-[a-f0-9]{12})\.yaml$/) + + if (uuidMatch) { + firstExecutionTrackingId = uuidMatch[1] + } else { + // Fallback: split by dots and get the last part before .yaml + const parts = newestLogFile.name.replace('.yaml', '').split('.') + if (parts.length >= 3) { + // The last part should be the tracking ID + firstExecutionTrackingId = parts[parts.length - 1] + } + } + + // If still not found, try to extract from YAML content + // Try different possible field name variations + if (!firstExecutionTrackingId) { + const patterns = [ + /executionTrackingID:\s*([^\s\n]+)/i, + /execution_tracking_id:\s*([^\s\n]+)/i, + /ExecutionTrackingID:\s*([^\s\n]+)/, + /executionTrackingId:\s*([^\s\n]+)/i, + ] + + for (const pattern of patterns) { + const match = logFileContent.match(pattern) + if (match) { + firstExecutionTrackingId = match[1].trim() + break + } + } + } + + expect(firstExecutionTrackingId).to.not.be.null + expect(firstExecutionTrackingId.length).to.be.greaterThan(0) + + // Verify the log file name contains the tracking ID + expect(newestLogFile.name).to.include(firstExecutionTrackingId) + + // Verify the log file content contains the action (might be in actionTitle, actionConfigTitle, or title field) + const hasActionReference = logFileContent.includes('Echo Test') || + logFileContent.includes('echo') || + logFileContent.includes('actionTitle') || + logFileContent.includes('actionConfigTitle') + expect(hasActionReference).to.be.true + }) + + it('Restart service and verify logs are loaded from disk', async function () { + this.timeout(60000) + + // Skip if first test didn't set the tracking ID + if (!firstExecutionTrackingId) { + this.skip() + } + + // Verify log file exists before restart + const logFilesBeforeRestart = fs.readdirSync(logsDir).filter(f => f.endsWith('.yaml')) + expect(logFilesBeforeRestart.length).to.be.greaterThan(0, 'Log file should exist before restart') + + // Find the log file for this execution + const matchingLogFileBefore = logFilesBeforeRestart.find(f => f.includes(firstExecutionTrackingId)) + expect(matchingLogFileBefore).to.not.be.undefined + + // Stop the current service instance + await runner.stop() + + // Wait a moment to ensure the process has fully stopped + await new Promise((resolve) => setTimeout(resolve, 2000)) + + // Verify log file still exists after stop (should not be deleted) + const logFilesAfterStop = fs.readdirSync(logsDir).filter(f => f.endsWith('.yaml')) + expect(logFilesAfterStop.length).to.be.greaterThan(0, 'Log file should still exist after service stop') + + const matchingLogFileAfter = logFilesAfterStop.find(f => f.includes(firstExecutionTrackingId)) + expect(matchingLogFileAfter).to.not.be.undefined + + // Start a new service instance (logs should be loaded from disk) + await runner.start('logPersistence') + + // Wait for the service to fully start and load logs + await new Promise((resolve) => setTimeout(resolve, 3000)) + + await getRootAndWait() + + // Navigate directly to the specific log entry (this verifies the log was loaded) + await webdriver.get(runner.baseUrl() + 'logs/' + firstExecutionTrackingId) + + // Wait for the log details page to load + await webdriver.wait( + new Condition('wait for log details to load', async () => { + try { + const body = await webdriver.findElement(By.tagName('body')) + const text = await body.getText() + // The log should contain the output from the echo command + return text.includes('Hello from persisted log test') || text.includes(firstExecutionTrackingId) + } catch (e) { + return false + } + }), + 15000 + ) + + // Verify the log content is displayed + const body = await webdriver.findElement(By.tagName('body')) + const bodyText = await body.getText() + + // The persisted log should be accessible and contain the expected output + expect(bodyText).to.include('Hello from persisted log test') + }) + + it('Verify log file still exists after restart', async function () { + // Skip if first test didn't set the tracking ID + if (!firstExecutionTrackingId) { + this.skip() + } + + // Verify the log file still exists on disk + const logFiles = fs.readdirSync(logsDir).filter(f => f.endsWith('.yaml')) + expect(logFiles.length).to.be.greaterThan(0, 'Log files should still exist after restart') + + // Find the log file for the first execution + const matchingLogFile = logFiles.find(f => f.includes(firstExecutionTrackingId)) + expect(matchingLogFile).to.not.be.undefined + expect(matchingLogFile).to.not.be.null + + // Verify the log file content is still valid + const logFilePath = path.join(logsDir, matchingLogFile) + const logFileContent = fs.readFileSync(logFilePath, 'utf8') + expect(logFileContent.length).to.be.greaterThan(0, 'Log file should not be empty') + + // The filename contains the tracking ID, so verify that + expect(matchingLogFile).to.include(firstExecutionTrackingId) + + // Verify the file contains some expected content (action reference) + const hasActionReference = logFileContent.includes('Echo Test') || + logFileContent.includes('echo') || + logFileContent.includes('actionTitle') || + logFileContent.includes('actionConfigTitle') + expect(hasActionReference).to.be.true + }) +}) diff --git a/service/internal/executor/loadlogs.go b/service/internal/executor/loadlogs.go new file mode 100644 index 0000000..6a03ae9 --- /dev/null +++ b/service/internal/executor/loadlogs.go @@ -0,0 +1,216 @@ +package executor + +import ( + "os" + "path/filepath" + "sort" + "strings" + + log "github.com/sirupsen/logrus" + "gopkg.in/yaml.v3" +) + +// LoadLogsFromDisk loads persisted logs from YAML files on disk and restores them to the executor. +// This should be called during startup if saveLogs is configured. +func (e *Executor) LoadLogsFromDisk() { + resultsDir := e.Cfg.SaveLogs.ResultsDirectory + if resultsDir == "" { + return + } + + entries, skippedCount := e.readLogDirectory(resultsDir) + if entries == nil { + return + } + + loadedLogs, skippedCount := e.parseLogFiles(resultsDir, entries, skippedCount) + + sort.Slice(loadedLogs, func(i, j int) bool { + return loadedLogs[i].DatetimeStarted.Before(loadedLogs[j].DatetimeStarted) + }) + + skippedCount = e.restoreLogsToExecutor(loadedLogs, skippedCount) + + log.WithFields(log.Fields{ + "loaded": len(loadedLogs), + "skipped": skippedCount, + }).Info("Finished loading persisted logs from disk") +} + +// readLogDirectory reads the log directory and returns entries, or nil if the directory doesn't exist or can't be read. +func (e *Executor) readLogDirectory(resultsDir string) ([]os.DirEntry, int) { + if _, err := os.Stat(resultsDir); os.IsNotExist(err) { + log.WithFields(log.Fields{ + "directory": resultsDir, + }).Debug("Logs directory does not exist, skipping log loading") + return nil, 0 + } + + log.WithFields(log.Fields{ + "directory": resultsDir, + }).Info("Loading persisted logs from disk") + + entries, err := os.ReadDir(resultsDir) + if err != nil { + log.WithFields(log.Fields{ + "directory": resultsDir, + "error": err, + }).Warnf("Failed to read logs directory") + return nil, 0 + } + + return entries, 0 +} + +// parseLogFiles parses YAML log files from the directory entries. +func (e *Executor) parseLogFiles(resultsDir string, entries []os.DirEntry, skippedCount int) ([]*InternalLogEntry, int) { + loadedLogs := make([]*InternalLogEntry, 0) + + for _, entry := range entries { + if !e.shouldProcessLogEntry(entry) { + continue + } + + logEntry, newSkippedCount := e.processLogFileEntry(resultsDir, entry.Name()) + skippedCount += newSkippedCount + if logEntry != nil { + loadedLogs = append(loadedLogs, logEntry) + } + } + + return loadedLogs, skippedCount +} + +// shouldProcessLogEntry checks if a directory entry should be processed as a log file. +func (e *Executor) shouldProcessLogEntry(entry os.DirEntry) bool { + return !entry.IsDir() && strings.HasSuffix(entry.Name(), ".yaml") +} + +// processLogFileEntry processes a single log file entry and returns the log entry or nil if it should be skipped. +func (e *Executor) processLogFileEntry(resultsDir, filename string) (*InternalLogEntry, int) { + logEntry, ok := e.loadLogFileFromPath(resultsDir, filename) + if !ok { + return nil, 1 + } + + if logEntry.ExecutionTrackingID == "" { + log.WithFields(log.Fields{ + "file": filepath.Join(resultsDir, filename), + }).Warnf("Log file missing execution tracking ID, skipping") + return nil, 1 + } + + e.restoreBindingForLogEntry(logEntry, filepath.Join(resultsDir, filename)) + return logEntry, 0 +} + +// loadLogFileFromPath loads and unmarshals a single log file. +func (e *Executor) loadLogFileFromPath(resultsDir, filename string) (*InternalLogEntry, bool) { + filepath := filepath.Join(resultsDir, filename) + data, err := os.ReadFile(filepath) + if err != nil { + log.WithFields(log.Fields{ + "file": filepath, + "error": err, + }).Warnf("Failed to read log file") + return nil, false + } + + var logEntry InternalLogEntry + if err := yaml.Unmarshal(data, &logEntry); err != nil { + log.WithFields(log.Fields{ + "file": filepath, + "error": err, + }).Warnf("Failed to unmarshal log file") + return nil, false + } + + return &logEntry, true +} + +// restoreBindingForLogEntry attempts to restore the binding for a log entry if it's missing or invalid. +func (e *Executor) restoreBindingForLogEntry(logEntry *InternalLogEntry, filepath string) { + if e.hasValidBinding(logEntry) || logEntry.ActionConfigTitle == "" { + return + } + + binding := e.findBindingByActionTitle(logEntry.ActionConfigTitle, logEntry.EntityPrefix) + if binding != nil { + logEntry.Binding = binding + return + } + + e.logBindingNotFound(logEntry, filepath) + logEntry.Binding = nil +} + +// hasValidBinding checks if a log entry has a valid binding. +func (e *Executor) hasValidBinding(logEntry *InternalLogEntry) bool { + return logEntry.Binding != nil && logEntry.Binding.Action != nil +} + +// logBindingNotFound logs a debug message when a binding cannot be found for a log entry. +func (e *Executor) logBindingNotFound(logEntry *InternalLogEntry, filepath string) { + log.WithFields(log.Fields{ + "file": filepath, + "actionTitle": logEntry.ActionConfigTitle, + "entityPrefix": logEntry.EntityPrefix, + "trackingId": logEntry.ExecutionTrackingID, + }).Debug("Could not find binding for log entry, loading without binding") +} + +// restoreLogsToExecutor restores loaded logs to the executor's internal structures. +func (e *Executor) restoreLogsToExecutor(loadedLogs []*InternalLogEntry, skippedCount int) int { + e.logmutex.Lock() + defer e.logmutex.Unlock() + + for _, logEntry := range loadedLogs { + if _, exists := e.logs[logEntry.ExecutionTrackingID]; exists { + log.WithFields(log.Fields{ + "trackingId": logEntry.ExecutionTrackingID, + }).Debug("Log entry already exists, skipping") + skippedCount++ + continue + } + + logEntry.Index = int64(len(e.logsTrackingIdsByDate)) + e.logs[logEntry.ExecutionTrackingID] = logEntry + e.logsTrackingIdsByDate = append(e.logsTrackingIdsByDate, logEntry.ExecutionTrackingID) + + if logEntry.Binding != nil { + e.addLogToBindingMap(logEntry) + } + } + + return skippedCount +} + +// addLogToBindingMap adds a log entry to the LogsByBindingId map. +func (e *Executor) addLogToBindingMap(logEntry *InternalLogEntry) { + if _, containsKey := e.LogsByBindingId[logEntry.Binding.ID]; !containsKey { + e.LogsByBindingId[logEntry.Binding.ID] = make([]*InternalLogEntry, 0) + } + e.LogsByBindingId[logEntry.Binding.ID] = append(e.LogsByBindingId[logEntry.Binding.ID], logEntry) +} + +// findBindingByActionTitle attempts to find a binding by matching the action config title and entity prefix. +func (e *Executor) findBindingByActionTitle(actionConfigTitle string, entityPrefix string) *ActionBinding { + e.MapActionBindingsLock.RLock() + defer e.MapActionBindingsLock.RUnlock() + + for _, binding := range e.MapActionBindings { + if binding.Action.Title == actionConfigTitle && e.matchesEntityPrefix(binding, entityPrefix) { + return binding + } + } + + return nil +} + +// matchesEntityPrefix checks if a binding matches the given entity prefix. +func (e *Executor) matchesEntityPrefix(binding *ActionBinding, entityPrefix string) bool { + if entityPrefix == "" { + return binding.Entity == nil + } + return binding.Entity != nil && binding.Entity.UniqueKey == entityPrefix +} diff --git a/service/main.go b/service/main.go index dbf4878..eeb2ca8 100644 --- a/service/main.go +++ b/service/main.go @@ -257,6 +257,8 @@ func main() { executor.RebuildActionMap() config.AddListener(executor.RebuildActionMap) + executor.LoadLogsFromDisk() + go onstartup.Execute(cfg, executor) go oncron.Schedule(cfg, executor) go onfileindir.WatchFilesInDirectory(cfg, executor)